search

envoyproxy / envoy

Cloud-native high-performance edge/middle/service proxy
https://www.envoyproxy.io
Apache License 2.0
25k stars 4.81k forks source link

istio-ingress Intermittent failure and kong accesslog Connection reset by peer #20150

Closed cobb-tx closed 2 years ago

cobb-tx commented 2 years ago

I'll send issue in istio https://github.com/istio/istio/issues/37608

Bug Description

istio ingress Intermittent unavailable,nginx ingress available

it seems envoy close TCP wihtout send FIN pack。

Flow Path： kong ——》istio-ingress——》sidecar——》service

I recorded the istio-ingress debug log and i think is ok 

2022-02-25T08:50:03.274475Z debug   envoy conn_handler  [C4705416] new connection
2022-02-25T08:50:03.274489Z trace   envoy connection    [C4705416] socket event: 3
2022-02-25T08:50:03.274491Z trace   envoy connection    [C4705416] write ready
2022-02-25T08:50:03.274493Z trace   envoy connection    [C4705416] read ready. dispatch_buffered_data=false
2022-02-25T08:50:03.274510Z trace   envoy connection    [C4705416] read returns: 936
2022-02-25T08:50:03.274526Z trace   envoy connection    [C4705416] read error: Resource temporarily unavailable
2022-02-25T08:50:03.274540Z trace   envoy http  [C4705416] parsing 936 bytes
2022-02-25T08:50:03.274545Z trace   envoy http  [C4705416] message begin
2022-02-25T08:50:03.274553Z debug   envoy http  [C4705416] new stream
2022-02-25T08:50:03.274571Z trace   envoy http  [C4705416] completed header: key=Host value=lurker.testing00.svc
2022-02-25T08:50:03.274579Z trace   envoy http  [C4705416] completed header: key=Connection value=keep-alive
2022-02-25T08:50:03.274585Z trace   envoy http  [C4705416] completed header: key=X-Forwarded-For value=10.252.196.193
2022-02-25T08:50:03.274592Z trace   envoy http  [C4705416] completed header: key=X-Forwarded-Proto value=https
2022-02-25T08:50:03.274600Z trace   envoy http  [C4705416] completed header: key=X-Forwarded-Host value=arktest.renrenaiche.cn
2022-02-25T08:50:03.274604Z trace   envoy http  [C4705416] completed header: key=X-Forwarded-Port value=8443
2022-02-25T08:50:03.274610Z trace   envoy http  [C4705416] completed header: key=X-Real-IP value=10.252.196.193
2022-02-25T08:50:03.274614Z trace   envoy http  [C4705416] completed header: key=Cache-Control value=max-age=0
2022-02-25T08:50:03.274621Z trace   envoy http  [C4705416] completed header: key=sec-ch-ua value=" Not A;Brand";v="99", "Chromium";v="98", "Google Chrome";v="98"
2022-02-25T08:50:03.274624Z trace   envoy http  [C4705416] completed header: key=sec-ch-ua-mobile value=?0
2022-02-25T08:50:03.274628Z trace   envoy http  [C4705416] completed header: key=sec-ch-ua-platform value="Windows"
2022-02-25T08:50:03.274630Z trace   envoy http  [C4705416] completed header: key=Upgrade-Insecure-Requests value=1
2022-02-25T08:50:03.274635Z trace   envoy http  [C4705416] completed header: key=User-Agent value=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.102 Safari/537.36
2022-02-25T08:50:03.274640Z trace   envoy http  [C4705416] completed header: key=Accept value=text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
2022-02-25T08:50:03.274652Z trace   envoy http  [C4705416] completed header: key=Sec-Fetch-Site value=none
2022-02-25T08:50:03.274657Z trace   envoy http  [C4705416] completed header: key=Sec-Fetch-Mode value=navigate
2022-02-25T08:50:03.274661Z trace   envoy http  [C4705416] completed header: key=Sec-Fetch-User value=?1
2022-02-25T08:50:03.274664Z trace   envoy http  [C4705416] completed header: key=Sec-Fetch-Dest value=document
2022-02-25T08:50:03.274667Z trace   envoy http  [C4705416] completed header: key=Accept-Encoding value=gzip, deflate, br
2022-02-25T08:50:03.274671Z trace   envoy http  [C4705416] completed header: key=Accept-Language value=zh,zh-CN;q=0.9,en;q=0.8
2022-02-25T08:50:03.274675Z trace   envoy http  [C4705416] onHeadersCompleteBase
2022-02-25T08:50:03.274677Z trace   envoy http  [C4705416] completed header: key=Cookie value=_ga=GA1.2.903401364.1631869824
2022-02-25T08:50:03.274682Z trace   envoy http  [C4705416] Server: onHeadersComplete size=21
2022-02-25T08:50:03.274694Z trace   envoy http  [C4705416] message complete
2022-02-25T08:50:03.274698Z trace   envoy connection    [C4705416] readDisable: disable=true disable_count=0 state=0 buffer_length=936
2022-02-25T08:50:03.274722Z debug   envoy http  [C4705416][S5712307922167558973] request headers complete (end_stream=true):
2022-02-25T08:50:03.274726Z debug   envoy http  [C4705416][S5712307922167558973] request end stream
2022-02-25T08:50:03.274829Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fcdf16f3b0 status=0
2022-02-25T08:50:03.274837Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fce3cbf960 status=0
2022-02-25T08:50:03.274842Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fcd0682cb0 status=0
2022-02-25T08:50:03.274851Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fce62b5960 status=0
2022-02-25T08:50:03.274921Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fcd06836c0 status=0
2022-02-25T08:50:03.274928Z debug   envoy router    [C4705416][S5712307922167558973] cluster 'outbound|80|v1|xxx.testing00.svc.xxxx.cn' match for URL '/api/user/common_public_variables?city=&fr='
2022-02-25T08:50:03.274985Z debug   envoy router    [C4705416][S5712307922167558973] router decoding headers:
2022-02-25T08:50:03.275019Z debug   envoy router    [C4705416][S5712307922167558973] pool ready
2022-02-25T08:50:03.275053Z trace   envoy http  [C4705416][S5712307922167558973] decode headers called: filter=0x55fce3cbee00 status=1
2022-02-25T08:50:03.275057Z trace   envoy http  [C4705416] parsed 936 bytes
2022-02-25T08:50:03.275065Z trace   envoy connection    [C4705416] socket event: 2
2022-02-25T08:50:03.275070Z trace   envoy connection    [C4705416] write ready
2022-02-25T08:50:03.290927Z debug   envoy router    [C4705416][S5712307922167558973] upstream headers complete: end_stream=false
2022-02-25T08:50:03.290956Z trace   envoy http  [C4705416][S5712307922167558973] encode headers called: filter=0x55fce62b58f0 status=0
2022-02-25T08:50:03.290965Z trace   envoy http  [C4705416][S5712307922167558973] encode headers called: filter=0x55fcd0682fc0 status=0
2022-02-25T08:50:03.290968Z trace   envoy http  [C4705416][S5712307922167558973] encode headers called: filter=0x55fcd06829a0 status=0
2022-02-25T08:50:03.290971Z trace   envoy http  [C4705416][S5712307922167558973] encode headers called: filter=0x55fcd06830a0 status=0
2022-02-25T08:50:03.290988Z trace   envoy http  [C4705416][S5712307922167558973] encode headers called: filter=0x55fce3fe6690 status=0
2022-02-25T08:50:03.291004Z debug   envoy http  [C4705416][S5712307922167558973] encoding headers via codec (end_stream=false):
2022-02-25T08:50:03.291017Z trace   envoy connection    [C4705416] writing 816 bytes, end_stream false
2022-02-25T08:50:03.291030Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fce62b58f0 status=0
2022-02-25T08:50:03.291034Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd0682fc0 status=0
2022-02-25T08:50:03.291058Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd06829a0 status=0
2022-02-25T08:50:03.291061Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd06830a0 status=0
2022-02-25T08:50:03.291065Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fce3fe6690 status=0
2022-02-25T08:50:03.291069Z trace   envoy http  [C4705416][S5712307922167558973] encoding data via codec (size=610 end_stream=false)
2022-02-25T08:50:03.291073Z trace   envoy connection    [C4705416] writing 610 bytes, end_stream false
2022-02-25T08:50:03.291099Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fce62b58f0 status=0
2022-02-25T08:50:03.291107Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd0682fc0 status=0
2022-02-25T08:50:03.291109Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd06829a0 status=0
2022-02-25T08:50:03.291122Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fcd06830a0 status=0
2022-02-25T08:50:03.291124Z trace   envoy http  [C4705416][S5712307922167558973] encode data called: filter=0x55fce3fe6690 status=0
2022-02-25T08:50:03.291127Z trace   envoy http  [C4705416][S5712307922167558973] encoding data via codec (size=0 end_stream=true)
2022-02-25T08:50:03.291131Z trace   envoy connection    [C4705416] readDisable: disable=false disable_count=1 state=0 buffer_length=0
2022-02-25T08:50:03.291333Z trace   envoy connection    [C4705416] socket event: 2
2022-02-25T08:50:03.291334Z trace   envoy connection    [C4705416] write ready
2022-02-25T08:50:03.291372Z trace   envoy connection    [C4705416] write returns: 1426

but kong log error like this （Please ignore the time difference） access.log upstream_status=[502, 200]

remote_addr=[10.170.20.xxx] http_x_forward=[xxx.16.196.14] time=[01/Mar/2022:10:44:43 +0800] request=[GET /js/5.9f2xxda.js HTTP/1.1] status=[200] byte=[9647] elapsed=[0.020] refer=[http://xxxx.xxx.cn/] body=[-] ua=[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.109 Safari/537.36] cookie=[xxxx] host=[xxx.xxx.cn] log_id=[-] consumer_id=[-] consumer_username=[-] trace_id=[-] spy_id=[-] upstream_response_time=[0.000, 0.002] sent_http_set_cookie=[-] authorization=[-] GATEWAY-LOGIN-TOKEN=[-] x_request_id=[-] upstream_ip=[172.26.0.89:31080, 172.26.0.89:31080] upstream_status=[502, 200]

error.log

2022/03/01 10:40:45 [error] 657813#0: *129921068 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 114.242.248.79, server: kong, request: "GET /xxxx/v1/workorder/count_summary_v2?selected_inspector_id=-1&user_id=174181&app_token=xxx HTTP/1.1", upstream: "http://172.26.0.67:31080/v1/workorder/count_summary_v2?app_token=xxxx", host: "xxxx.testing.svc"

and I use tcpdump

A6FC4D17-8A63-4577-A81C-75643565F364

what can i do to fix this bug？

Version

$ istioctl version
client version: 1.10.0
control plane version: 1.10.0
data plane version: 1.10.0 (301 proxies)

$ kubectl version --short
Client Version: v1.20.0
Server Version: v1.20.6

$ helm version --short
v3.4.2+g23dd3af

Additional Information

No response

rojkov commented 2 years ago

I don't really understand what is wrong exactly (Envoy doesn't close a connection when the peer resets it?) and where Envoy is sitting in this setup.

Perhaps @alyssawilk @lizan could help.

alyssawilk commented 2 years ago

if Envoy is setting up for a connection close and not sending a FIN could it be because of the delay close? have you tried turning that delay down and seeing if it helps?

cobb-tx commented 2 years ago

@rojkov sorry I describe is not very clear. the peer resets it， probably because the envoy （istio-ingress）close connection without FIN I guess。 and This is by intermittent

cobb-tx commented 2 years ago

@alyssawilk i will try it. I tried before timeout and keeplive but It's not working

cobb-tx commented 2 years ago

i will close this issue because this bug not envoy，it is kube-proxy problem and i will The process of troubleshooting a problem in next

cobb-tx commented 2 years ago

i find this can fix this bug but incomplete because There will be more 502

ipvsadm --set 7500 120 300

and we consider k8s-ingress（nginx） keeplive 75s There's reason No 502， i will test envoy timeout 75s