search

envoyproxy / envoy

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

Envoy frequently resets http2 stream on doing downstream filters with NO ERROR #17574

Closed Patrick0308 closed 3 years ago

Patrick0308 commented 3 years ago

If you are reporting any crash or any potential security issue, do not open an issue in this repo. Please report the issue via emailing envoy-security@googlegroups.com where the issue will be triaged appropriately.

Title: One line description

Description: Envoy resets http2 stream on doing downstream filters on outbound traffic. The problem does not appear until the server has been running for a period of time. I suspect there is a problem with the native jaeger tracing filter.

Repro steps:

Admin and Stats Output:

Include the admin output for the following endpoints: /stats, /clusters, /routes, /server_info. For more information, refer to the admin endpoint documentation.

Note: If there are privacy concerns, sanitize the data prior to

Config: config dump file: config_dump.txt

Logs:

2021-08-03T06:46:35.296966Z trace   envoy connection    [C355666] socket event: 3
2021-08-03T06:46:35.296969Z trace   envoy connection    [C355666] write ready
2021-08-03T06:46:35.296972Z trace   envoy connection    [C355666] read ready. dispatch_buffered_data=false
2021-08-03T06:46:35.296993Z trace   envoy connection    [C355666] read returns: 3880
2021-08-03T06:46:35.296999Z trace   envoy connection    [C355666] read error: Resource temporarily unavailable
2021-08-03T06:46:35.297003Z trace   envoy http2 [C355666] dispatching 3880 bytes
2021-08-03T06:46:35.297007Z trace   envoy http2 [C355666] about to recv frame type=4, flags=1
 2021-08-03T06:46:35.297009Z trace   envoy http2 [C355666] track inbound frame type=4 flags=1 length=0 padding_length=0
2021-08-03T06:46:35.297014Z trace   envoy http2 [C355666] recv frame type=4
2021-08-03T06:46:35.297016Z trace   envoy http2 [C355666] about to recv frame type=1, flags=4
2021-08-03T06:46:35.297021Z trace   envoy http2 [C355666] track inbound frame type=1 flags=4 length=1603 padding_length=0
 2021-08-03T06:46:35.297027Z debug   envoy http  [C355666] new stream
 2021-08-03T06:46:35.297118Z trace   envoy http2 [C355666] recv frame type=1
2021-08-03T06:46:35.297140Z debug   envoy http  [C355666][S10909270796817708085] request headers complete (end_stream=false):
':method', 'POST'
':scheme', 'http'
':path', '/auth.GatewayAuth/Check'
':authority', '172.22.211.139:8080'
'content-type', 'application/grpc+proto'
'user-agent', 'grpc-go/1.38.0'
 'te', 'trailers'
'grpc-timeout', '2999136u'
'x-platform', 'h5'
'accept', 'application/json'
'ip-region', 'HK'
'micro-endpoint', 'GatewayAuth.Check'
'x-os-version', 'Mac OS X10.15.7'
'x-refer-uri', '%2F'
'uber-trace-id', '127c39ccd8a4c250:74415da388f5e542:05832d39042841b4:1'
'x-timestamp', '1627973195291.575'
'x-api-key', 'a0f3fbef3db9195187dd6d00f1501a1b'
'x-forwarded-for', '103.97.201.31, 18.162.88.93, 172.22.170.128, 127.0.0.6'
'x-features', 'stock.industryComparison,portfolio.profitAnalysisV2,share.twitter,social.create_group,topic_payment,social.security_user,ipo.tradeV2,stock.industry_concept,flutter.event,stock.new_main_industry,social.signed,news.live,share.facebook,news.relatedEvent,stock.supply_chain_v2,quote.mall,quote.change,UTP,trade.lb_condition_tsl_ratio,stock.darkV2,news.filings,stock.supply_chain_v4,ipo.list,fund.investment,industry.chain,social_wallet,accounts.fund,open.passport,trade.commission,trade.condition,IPOServiceHongkongFinancing,lb.rms,social.learning,lb-staff,account_channel.pspl_sg.default,StockHoldingLBAvgCost,stock.supply_chain,stock.supply_chain_v3,quote.changeV2,order.submit,grounding.huawei,markets.jp,trade.lb_condition,accounts.sip,trade.statistics,deep.data,social.share_order,news.recommendation_posts,news.filingsV2,follow.open_account_close,share.instagram,markets.sg,rms.open,thirdLogin.twitter,share.whatsapp,stock.dark,markets.cn,markets.uk,talent,trade.lb_condition_mit,accounts.companyAuth,test.verify_id,college_creator_web,thirdLogin.facebook,test1111,watchlist.following,hkmarket.dark.trade,live.trading'
'x-trace-id', '127c39ccd8a4c250'
'micro-from-service', 'lb.gateway.api'
'ip-mainland', 'false'
'timeout', '3000000000'
'accept-language', 'zh-CN'
'x-host', 'api.longbridge.xyz'
'x-stage', 'prod'
'x-api-signature', 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
'x-content-type', 'application/grpc+proto'
'x-device-model', 'Chrome Mac OS X 10.15.7'
'x-from-cluster', 'HK-1'
'x-real-ip', '103.97.201.31'
 'micro-service', 'lb.gateway.auth'
'x-request-id', '127c39ccd8a4c250'
'ip-city', 'unknown'
'accept-encoding', 'gzip'
'x-user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36'
 2021-08-03T06:46:35.297193Z trace   envoy wasm  [host->vm] proxy_on_context_create(510972, 1)
2021-08-03T06:46:35.297204Z trace   envoy wasm  [vm->host] env.proxy_get_property(5343344, 19, 5319884, 5319880)
2021-08-03T06:46:35.297208Z trace   envoy wasm  [host->vm] malloc(8)
2021-08-03T06:46:35.297212Z trace   envoy wasm  [host<-vm] malloc return: 5325152
2021-08-03T06:46:35.297214Z trace   envoy wasm  [vm<-host] env.proxy_get_property return: 0
2021-08-03T06:46:35.297218Z trace   envoy wasm  [host<-vm] proxy_on_context_create return: void
2021-08-03T06:46:35.297221Z trace   envoy wasm  [host->vm] proxy_on_request_headers(510972, 37, 0)
2021-08-03T06:46:35.297225Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4966, 24, 5319920, 5319904)
2021-08-03T06:46:35.297229Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-03T06:46:35.297231Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4944, 21, 5319920, 5319904)
2021-08-03T06:46:35.297234Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-03T06:46:35.297238Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4944, 21, 5322240, 904)
2021-08-03T06:46:35.297244Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-03T06:46:35.297247Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4966, 24, 5325576, 87)
2021-08-03T06:46:35.297250Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-03T06:46:35.297253Z trace   envoy wasm  [host<-vm] proxy_on_request_headers return: 0
2021-08-03T06:46:35.297256Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a32dccb0 status=0
2021-08-03T06:46:35.297262Z debug   envoy filter    override with 3 ALPNs
2021-08-03T06:46:35.297266Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a3b210a0 status=0
2021-08-03T06:46:35.297269Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a203efc0 status=0
2021-08-03T06:46:35.297272Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a99e458d90 status=0
2021-08-03T06:46:35.297276Z debug   envoy http  [C355666][S10909270796817708085] doEndStream() resetting stream
2021-08-03T06:46:35.297279Z debug   envoy http  [C355666][S10909270796817708085] stream reset
2021-08-03T06:46:35.297301Z trace   envoy wasm  [host->vm] proxy_on_log(510972)
2021-08-03T06:46:35.297301Z trace   envoy wasm  [host->vm] proxy_on_log(510972)
2021-08-03T06:46:35.297307Z trace   envoy wasm  [host<-vm] proxy_on_log return: void
2021-08-03T06:46:35.297310Z trace   envoy wasm  [host->vm] proxy_on_done(510972)
2021-08-03T06:46:35.297313Z trace   envoy wasm  [host<-vm] proxy_on_done return: 1
2021-08-03T06:46:35.297315Z trace   envoy wasm  [host->vm] proxy_on_delete(510972)
2021-08-03T06:46:35.297318Z trace   envoy wasm  [host<-vm] proxy_on_delete return: void
2021-08-03T06:46:35.297321Z trace   envoy main  item added to deferred deletion list (size=1)
2021-08-03T06:46:35.297326Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a32dcb60 status=1
2021-08-03T06:46:35.297331Z trace   envoy http2 [C355666] dispatched 3880 bytes
2021-08-03T06:46:35.297335Z trace   envoy http2 [C355666] about to send frame type=3, flags=0
2021-08-03T06:46:35.297337Z trace   envoy http2 [C355666] send data: bytes=13
2021-08-03T06:46:35.297341Z trace   envoy connection    [C355666] writing 13 bytes, end_stream false
2021-08-03T06:46:35.297345Z trace   envoy http2 [C355666] sent frame type=3
2021-08-03T06:46:35.297347Z debug   envoy http2 [C355666] sent reset code=0
2021-08-03T06:46:35.297350Z debug   envoy http2 [C355666] stream closed: 0
2021-08-03T06:46:35.297352Z trace   envoy main  item added to deferred deletion list (size=2)
2021-08-03T06:46:35.297357Z trace   envoy main  clearing deferred deletion list (size=2)
2021-08-03T06:46:35.297373Z trace   envoy connection    [C355666] socket event: 2
2021-08-03T06:46:35.297379Z trace   envoy connection    [C355666] write ready
2021-08-03T06:46:35.297401Z trace   envoy connection    [C355666] write returns: 13
2021-08-03T06:46:35.297823Z trace   envoy connection    [C355666] socket event: 3
2021-08-03T06:46:35.297849Z trace   envoy connection    [C355308] socket event: 3
2021-08-03T06:46:35.297877Z trace   envoy connection    [C355308] write ready
2021-08-03T06:46:35.297883Z trace   envoy connection    [C355308] read ready. dispatch_buffered_data=false
2021-08-03T06:46:35.297894Z trace   envoy connection    [C355308] read returns: 603
2021-08-03T06:46:35.297926Z trace   envoy connection    [C355308] read error: Resource temporarily unavailable
2021-08-03T06:46:35.297896Z trace   envoy connection    [C355666] write ready
2021-08-03T06:46:35.297970Z trace   envoy connection    [C355666] read ready. dispatch_buffered_data=false
2021-08-03T06:46:35.297978Z trace   envoy connection    [C355666] read returns: 0
2021-08-03T06:46:35.297981Z debug   envoy connection    [C355666] remote close
2021-08-03T06:46:35.297983Z debug   envoy connection    [C355666] closing socket: 0
2021-08-03T06:46:35.298025Z trace   envoy connection    [C355666] raising connection event 0
2021-08-03T06:46:35.298034Z debug   envoy conn_handler  [C355666] adding to cleanup list
2021-08-03T06:46:35.298037Z trace   envoy main  item added to deferred deletion list (size=1)
2021-08-03T06:46:35.298040Z trace   envoy main  item added to deferred deletion list (size=2)
2021-08-03T06:46:35.298043Z trace   envoy main  clearing deferred deletion list (size=2)
2021-08-03T06:46:35.298073Z trace   envoy http  [C355308] parsing 603 bytes
2021-08-03T06:46:35.298080Z trace   envoy http  [C355308] message begin
2021-08-03T06:46:35.298090Z trace   envoy http  [C355308] completed header: key=Server value=openresty
2021-08-03T06:46:35.298097Z trace   envoy http  [C355308] completed header: key=Date value=Tue, 03 Aug 2021 06:46:35 GMT
 2021-08-03T06:46:35.298101Z trace   envoy http  [C355308] completed header: key=Content-Type value=application/json
2021-08-03T06:46:35.298107Z trace   envoy http  [C355308] completed header: key=Content-Length value=72
2021-08-03T06:46:35.298111Z trace   envoy http  [C355308] completed header: key=Connection value=keep-alive
 2021-08-03T06:46:35.298116Z trace   envoy http  [C355308] completed header: key=X-Lua-Resty-WAF-ID value=149bec1c61988cff9a12
2021-08-03T06:46:35.298120Z trace   envoy http  [C355308] completed header: key=X-Request-Id value=6551b551-45dc-427f-9a9c-94bde90f6ba6
2021-08-03T06:46:35.298124Z trace   envoy http  [C355308] completed header: key=X-Endpoint value=GET /v1/common/carousel-list
 2021-08-03T06:46:35.298128Z trace   envoy http  [C355308] completed header: key=X-Scope value=activity-api
2021-08-03T06:46:35.298131Z trace   envoy http  [C355308] completed header: key=X-Error-Code value=13
 2021-08-03T06:46:35.298134Z trace   envoy http  [C355308] completed header: key=X-Stage value=prod
 2021-08-03T06:46:35.298137Z trace   envoy http  [C355308] completed header: key=X-Trace-Id value=127c39ccd8a4c250
2021-08-03T06:46:35.298141Z trace   envoy http  [C355308] completed header: key=X-Err-Detail value=stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR
 2021-08-03T06:46:35.298144Z trace   envoy http  [C355308] onHeadersCompleteBase
2021-08-03T06:46:35.298147Z trace   envoy http  [C355308] completed header: key=Strict-Transport-Security value=max-age=31536000; includeSubDomains
 2021-08-03T06:46:35.298151Z trace   envoy http  [C355308] status_code 500
 2021-08-03T06:46:35.298154Z trace   envoy http  [C355308] Client: onHeadersComplete size=14
2021-08-03T06:46:35.298167Z debug   envoy router    [C355307][S7053141334668950040] upstream headers complete: end_stream=false
 2021-08-03T06:46:35.298213Z trace   envoy wasm  [host->vm] proxy_on_response_headers(167748, 16, 0)
2021-08-03T06:46:35.298229Z trace   envoy wasm  [host<-vm] proxy_on_response_headers return: 0132390   │ 2021-2021008-03T06:46:35.298232Z trace   envoy http  [C355307][S7053141334668950040] encode headers called: filter=0x55a9a32dd0a0 status=0
2021-08-03T06:46:35.298235Z trace   envoy http  [C355307][S7053141334668950040] encode headers called: filter=0x55a9a1e4db90 status=0
2021-08-03T06:46:35.298237Z trace   envoy http  [C355307][S7053141334668950040] encode headers called: filter=0x55a9a32ddab0 status=0
2021-08-03T06:46:35.298241Z trace   envoy wasm  [host->vm] proxy_on_response_headers(559039, 16, 0)
 2021-08-03T06:46:35.298249Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(2, 4966, 24, 5319920, 5319904)
2021-08-03T06:46:35.298259Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
 2021-08-03T06:46:35.298262Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(2, 4944, 21, 5319920, 5319904)
2021-08-03T06:46:35.298265Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-03T06:46:35.298269Z trace   envoy wasm  [host<-vm] proxy_on_response_headers return: 0
 2021-08-03T06:46:35.298270Z trace   envoy http  [C355307][S7053141334668950040] encode headers called: filter=0x55a9a015db90 status=0
 2021-08-03T06:46:35.298285Z debug   envoy http  [C355307][S7053141334668950040] encoding headers via codec (end_stream=false):
':status', '500'
'server', 'istio-envoy'
 'date', 'Tue, 03 Aug 2021 06:46:35 GMT'
'content-type', 'application/json'
'content-length', '72'
 'x-lua-resty-waf-id', '149bec1c61988cff9a12'
 'x-request-id', '6551b551-45dc-427f-9a9c-94bde90f6ba6'
'x-endpoint', 'GET /v1/common/carousel-list'
'x-scope', 'activity-api'
 'x-error-code', '13'
 'x-stage', 'prod'
 'x-trace-id', '127c39ccd8a4c250'
'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR'
'strict-transport-security', 'max-age=31536000; includeSubDomains'
 'x-envoy-upstream-service-time', '3'
 'x-envoy-decorator-operation', 'lb-gateway-api-istio.core.svc.cluster.local:80/*'

2021-08-03T06:46:35.298295Z trace   envoy connection    [C355307] writing 622 bytes, end_stream false
2021-08-03T06:46:35.298302Z trace   envoy http  [C355308] message complete

Note: If there are privacy concerns, sanitize the data prior to sharing.

Call Stack:

If the Envoy binary is crashing, a call stack is required. Please refer to the Bazel Stack trace documentation.

Patrick0308 commented 3 years ago

I remove the native jaeger tracing filter, but the problem also happen.

Patrick0308 commented 3 years ago

@lizan Hi, can you help us? This problem bothers us very much.

lizan commented 3 years ago

It seems 'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR' is from upstream but not Envoy itself, or your log is from different Envoy.

yankunsam commented 3 years ago

It seems 'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR' is from upstream but not Envoy itself, or your log is from different Envoy.

@lizan Is it related with 13349?

Patrick0308 commented 3 years ago

@lizan Thanks for your reply. This log is from a envoy. It has three incomplete calling process. Sorry, It's not clear to see. If this problem reproduce again. I will put new log in here.

It seems 'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR' is from upstream but not Envoy itself

I once suspected that this problem was caused by upstream server. But the following log confused me. Please see this stream called S10909270796817708085. 

2021-08-03T06:46:35.297256Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a32dccb0 status=0
2021-08-03T06:46:35.297262Z debug   envoy filter    override with 3 ALPNs
2021-08-03T06:46:35.297266Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a3b210a0 status=0
2021-08-03T06:46:35.297269Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a203efc0 status=0
2021-08-03T06:46:35.297272Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a99e458d90 status=0
2021-08-03T06:46:35.297276Z debug   envoy http  [C355666][S10909270796817708085] doEndStream() resetting stream
2021-08-03T06:46:35.297279Z debug   envoy http  [C355666][S10909270796817708085] stream reset
2021-08-03T06:46:35.297301Z trace   envoy wasm  [host->vm] proxy_on_log(510972)
2021-08-03T06:46:35.297301Z trace   envoy wasm  [host->vm] proxy_on_log(510972)
2021-08-03T06:46:35.297307Z trace   envoy wasm  [host<-vm] proxy_on_log return: void
2021-08-03T06:46:35.297310Z trace   envoy wasm  [host->vm] proxy_on_done(510972)
2021-08-03T06:46:35.297313Z trace   envoy wasm  [host<-vm] proxy_on_done return: 1
2021-08-03T06:46:35.297315Z trace   envoy wasm  [host->vm] proxy_on_delete(510972)
2021-08-03T06:46:35.297318Z trace   envoy wasm  [host<-vm] proxy_on_delete return: void
2021-08-03T06:46:35.297321Z trace   envoy main  item added to deferred deletion list (size=1)
2021-08-03T06:46:35.297326Z trace   envoy http  [C355666][S10909270796817708085] decode headers called: filter=0x55a9a32dcb60 status=1
2021-08-03T06:46:35.297331Z trace   envoy http2 [C355666] dispatched 3880 bytes
2021-08-03T06:46:35.297335Z trace   envoy http2 [C355666] about to send frame type=3, flags=0
2021-08-03T06:46:35.297337Z trace   envoy http2 [C355666] send data: bytes=13
2021-08-03T06:46:35.297341Z trace   envoy connection    [C355666] writing 13 bytes, end_stream false
2021-08-03T06:46:35.297345Z trace   envoy http2 [C355666] sent frame type=3
2021-08-03T06:46:35.297347Z debug   envoy http2 [C355666] sent reset code=0
2021-08-03T06:46:35.297350Z debug   envoy http2 [C355666] stream closed: 0

This is an outbound request. The route filter is not being executed. Is it connect to an upstream server ?

lizan commented 3 years ago

@Patrick0308 from the config_dump and the log of the stream, I suspect this is due to the Lua filter, any script error will result a reset stream: https://github.com/envoyproxy/envoy/blob/main/source/extensions/filters/http/lua/lua_filter.cc#L739-L744

You need to turn on log level to trace for lua and route as well to see if router is executed.

Patrick0308 commented 3 years ago

@lizan When envoy printed this log, I turned on log level to trace for all already.

 assert: trace
  backtrace: trace
  cache_filter: trace
  client: trace
  config: trace
  connection: trace
  conn_handler: trace
  decompression: trace
  dubbo: trace
  envoy_bug: trace
  ext_authz: trace
  rocketmq: trace
  file: trace
  filter: trace
  forward_proxy: trace
  grpc: trace
  hc: trace
  health_checker: trace
  http: trace
  http2: trace
  hystrix: trace
  init: trace
  io: trace
  jwt: trace
  kafka: trace
  lua: trace
  main: trace
  matcher: trace
  misc: error
  mongo: trace
  quic: trace
  quic_stream: trace
  pool: trace
  rbac: trace
  redis: trace
  router: trace
  runtime: trace
  stats: trace
  secret: trace
  tap: trace
  testing: trace
  thrift: trace
  tracing: trace
  upstream: trace
  udp: trace
  wasm: trace
Patrick0308 commented 3 years ago

Now this problem reproduce again. log:

2021-08-19T05:13:44.426548Z trace   envoy http2 [C198719] recv frame type=4
2021-08-19T05:13:44.426551Z trace   envoy http2 [C198719] about to recv frame type=1, flags=4
2021-08-19T05:13:44.426556Z trace   envoy http2 [C198719] track inbound frame type=1 flags=4 length=1980 padding_length=0
2021-08-19T05:13:44.426566Z debug   envoy http  [C198719] new stream
2021-08-19T05:13:44.426676Z trace   envoy http2 [C198719] recv frame type=1
2021-08-19T05:13:44.426704Z debug   envoy http  [C198719][S14573040038665154729] request headers complete (end_stream=false):
':method', 'POST'
':scheme', 'http'
':path', '/auth.GatewayAuth/Check'
':authority', '172.22.216.144:8080'
'content-type', 'application/grpc+proto'
'user-agent', 'grpc-go/1.39.0'
'te', 'trailers'
'grpc-timeout', '2999040u'
'x-device-id', '05BF909C-266D-4F87-8FD8-47BFFEB77F2C'
'x-device-name', 'iPhone%2012%20Pro%20Max%EF%BC%88%E7%A8%8B%E7%A8%8B%E7%A8%8B%EF%BC%89'
'x-forwarded-for', '112.17.164.168, 10.7.252.43, 118.193.38.147, 172.22.110.64, 127.0.0.6'
'x-os-version', '14.5'
'x-from-cluster', 'HK-1'
'x-application-build', '1'
'x-api-key', 'd038c0ab81396349d5e14fb149f32950'
'x-prefer-language', 'zh-CN'
'x-channel', 'IO000006'
'accept-language', 'zh-CN'
'x-user-agent', 'longbridge-ios-app/4.0.0 (iPhone; iOS 14.5; Scale/3.00)'
'micro-endpoint', 'GatewayAuth.Check'
'x-timestamp', '1629350023942.511'
'x-request-id', 'ad6f15e21c8b70f571e8ae2a95e677c5'
'timeout', '3000000000'
'x-application-version', '4.0.0'
'ip-mainland', 'true'
'ip-region', 'CN'
'accept', '*/*'
'x-api-signature', '**********'
'x-platform', 'ios'
'x-trace-id', 'ad6f15e21c8b70f571e8ae2a95e677c5'
'x-device-model', 'iPhone 12 Pro Max'
'x-bundle-id', 'global.longbridge.app.ios'
'x-host', 'api.longbridge.xyz'
'authorization', '**************'
'accept-encoding', 'gzip, deflate, br'
'x-content-type', 'application/grpc+proto'
'uber-trace-id', 'ad6f15e21c8b70f571e8ae2a95e677c5:415c3b0b6de5b8dc:31f1b2b19d7c0ed8:1'
'micro-service', 'lb.gateway.auth'
'ip-city', 'Hangzhou'
'x-stage', 'prod'
'micro-from-service', 'lb.gateway.api'
'x-real-ip', '112.17.164.168'
'x-features', 'accounts.fund,stock.industryComparison,share.whatsapp,open.passport,social.create_group,lb.rms,fortune.analysis,social.security_user,stock.supply_chain,stock.industry_concept,stock.supply_chain_v3,social.learning,lb-staff,order.submit,markets.sg,trade.condition,hkmarket.dark.trade,ipo.tradeV2,quote.mall,watchlist.following,accounts.companyAuth,accounts.sip,StockHoldingLBAvgCost,stock.supply_chain_v2,trade.lb_condition_tsl_ratio,stock.dark,markets.jp,markets.uk,stock.new_main_industry,fund.investment,industry.chain,quote.changeV2,share.instagram,stock.darkV2,news.relatedEvent,markets.cn,trade.commission,social.signed,share.facebook,trade.statistics,portfolio.profitAnalysisV2,talent,thirdLogin.facebook,thirdLogin.twitter,deep.data,news.filingsV2,news.filings,social.share_order,topic_payment,social_wallet,quote.change,trade.lb_condition_mit,live.trading,test.verify_id,UTP,trade.lb_condition,flutter.event,rms.open,ipo.list,follow.open_account_close,IPOServiceHongkongFinancing,news.live,share.twitter,finance.rating,news.recommendation_posts'

2021-08-19T05:13:44.426762Z trace   envoy wasm  [host->vm] proxy_on_context_create(737500, 1)
2021-08-19T05:13:44.426774Z trace   envoy wasm  [vm->host] env.proxy_get_property(5334440, 19, 5319884, 5319880)
2021-08-19T05:13:44.426779Z trace   envoy wasm  [host->vm] malloc(8)
2021-08-19T05:13:44.426783Z trace   envoy wasm  [host<-vm] malloc return: 5338128
2021-08-19T05:13:44.426785Z trace   envoy wasm  [vm<-host] env.proxy_get_property return: 0
2021-08-19T05:13:44.426789Z trace   envoy wasm  [host<-vm] proxy_on_context_create return: void
2021-08-19T05:13:44.426792Z trace   envoy wasm  [host->vm] proxy_on_request_headers(737500, 44, 0)
2021-08-19T05:13:44.426797Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4966, 24, 5319920, 5319904)
2021-08-19T05:13:44.426802Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-19T05:13:44.426804Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4944, 21, 5319920, 5319904)
2021-08-19T05:13:44.426807Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-19T05:13:44.426813Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4944, 21, 5322240, 904)
2021-08-19T05:13:44.426820Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-19T05:13:44.426822Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4966, 24, 5325576, 87)
2021-08-19T05:13:44.426826Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-19T05:13:44.426828Z trace   envoy wasm  [host<-vm] proxy_on_request_headers return: 0
2021-08-19T05:13:44.426831Z trace   envoy http  [C198719][S14573040038665154729] decode headers called: filter=0x5576c3197f80 status=0
2021-08-19T05:13:44.426839Z debug   envoy filter    override with 3 ALPNs
2021-08-19T05:13:44.426843Z trace   envoy http  [C198719][S14573040038665154729] decode headers called: filter=0x5576c1ade930 status=0
2021-08-19T05:13:44.426845Z debug   envoy filter    cors filter do decodeHeader
2021-08-19T05:13:44.426848Z trace   envoy http  [C198719][S14573040038665154729] decode headers called: filter=0x5576c3196a80 status=0
2021-08-19T05:13:44.426850Z debug   envoy filter    fault filter do decodeHeader
2021-08-19T05:13:44.426853Z trace   envoy http  [C198719][S14573040038665154729] decode headers called: filter=0x5576c3196770 status=0
2021-08-19T05:13:44.426863Z debug   envoy http  [C198719][S14573040038665154729] doEndStream() resetting stream
2021-08-19T05:13:44.426868Z debug   envoy http  [C198719][S14573040038665154729] stream reset
2021-08-19T05:13:44.426899Z trace   envoy wasm  [host->vm] proxy_on_log(737500)
2021-08-19T05:13:44.426903Z trace   envoy wasm  [host<-vm] proxy_on_log return: void
2021-08-19T05:13:44.426907Z trace   envoy wasm  [host->vm] proxy_on_done(737500)
2021-08-19T05:13:44.426910Z trace   envoy wasm  [host<-vm] proxy_on_done return: 1
2021-08-19T05:13:44.426912Z trace   envoy wasm  [host->vm] proxy_on_delete(737500)
2021-08-19T05:13:44.426915Z trace   envoy wasm  [host<-vm] proxy_on_delete return: void
2021-08-19T05:13:44.426918Z trace   envoy main  item added to deferred deletion list (size=1)
2021-08-19T05:13:44.426924Z trace   envoy http  [C198719][S14573040038665154729] decode headers called: filter=0x5576c3197490 status=1
2021-08-19T05:13:44.426929Z trace   envoy http2 [C198719] dispatched 4729 bytes
2021-08-19T05:13:44.426933Z trace   envoy http2 [C198719] about to send frame type=3, flags=0
2021-08-19T05:13:44.426935Z trace   envoy http2 [C198719] send data: bytes=13
2021-08-19T05:13:44.426939Z trace   envoy connection    [C198719] writing 13 bytes, end_stream false
2021-08-19T05:13:44.426943Z trace   envoy http2 [C198719] sent frame type=3
2021-08-19T05:13:44.426945Z debug   envoy http2 [C198719] sent reset code=0
2021-08-19T05:13:44.426948Z debug   envoy http2 [C198719] stream closed: 0

I add log at the begin of cors and fault filter decodeHeader function. For example

Http::FilterHeadersStatus FaultFilter::decodeHeaders(Http::RequestHeaderMap& headers, bool) {
  ENVOY_LOG(debug, "fault filter do decodeHeader");
  //...
}

config_dump file: envoy-error-config-dump.log

Patrick0308 commented 3 years ago

It seems like wasm filter or fault filter cause resetting stream.

yankunsam commented 3 years ago

It seems 'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR' is from upstream but not Envoy itself, or your log is from different Envoy.

I see "saw upstream close connection" in the envoy's log, like this, image

Does it mean that the server Pod's Envoy terminate this stream?

lizan commented 3 years ago

It seems 'x-err-detail', 'stream+terminated+by+RST_STREAM+with+error+code%3A+NO_ERROR' is from upstream but not Envoy itself, or your log is from different Envoy.

I see "saw upstream close connection" in the envoy's log, like this, image

Does it mean that the server Pod's Envoy terminate this stream?

This seems normal because upstream response is completed (one line above)

Patrick0308 commented 3 years ago

@lizan I add some log on wasm context's decodeHeaders function. 

Http::FilterHeadersStatus Context::decodeHeaders(Http::RequestHeaderMap& headers, bool end_stream) {
  ENVOY_LOG(debug, "wasm filter do decodeHeader");
  onCreate();
  ENVOY_LOG(debug, "wasm done onCreate");
  http_request_started_ = true;
  request_headers_ = &headers;
  end_of_stream_ = end_stream;
  auto result = convertFilterHeadersStatus(onRequestHeaders(headerSize(&headers), end_stream));
  if (result == Http::FilterHeadersStatus::Continue) {
    request_headers_ = nullptr;
  }
  return result;
}

When problem reproduce again, the log printed.

2021-08-23T07:47:01.420308Z trace   envoy http2 [C291517] recv frame type=1
2021-08-23T07:47:01.421740Z trace   envoy wasm  [host<-vm] proxy_on_log return: void
2021-08-23T07:47:01.421862Z debug   envoy http  [C291517][S4289254375588132466] request headers complete (end_stream=false):
':method', 'POST'
':scheme', 'http'
':path', '/go.MemberAuth/SendCode'
':authority', '172.22.150.57:8080'
'content-type', 'application/grpc+json'
'user-agent', 'grpc-go/1.39.0'
'te', 'trailers'
'grpc-timeout', '5998760u'
'x-forwarded-for', '118.122.97.128, 10.7.252.44, 152.32.213.111, 172.22.74.64, 127.0.0.6'
'ip-region', 'CN'
'x-features', 'test.verify_id,ipo.list,trade.lb_condition_tsl_ratio,share.whatsapp,stock.darkV2,accounts.companyAuth,stock.new_main_industry,social.create_group,portfolio.profitAnalysisV2,follow.open_account_close,trade.lb_condition,thirdLogin.twitter,news.filingsV2,watchlist.following,markets.uk,live.trading,stock.industryComparison,talent,hkmarket.dark.trade,industry.chain,markets.cn,quote.mall,news.live,order.submit,share.instagram,social.security_user,news.recommendation_posts,stock.supply_chain_v3,social.signed,topic_payment,quote.change,fortune.analysis,markets.sg,stock.supply_chain,news.filings,social.share_order,lb.rms,trade.statistics,deep.data,accounts.fund,rms.open,share.twitter,markets.jp,stock.industry_concept,stock.supply_chain_v4,stock.dark,UTP,thirdLogin.facebook,ipo.tradeV2,flutter.event,IPOServiceHongkongFinancing,news.relatedEvent,StockHoldingLBAvgCost,open.passport,social.learning,lb-staff,finance.rating,accounts.sip,social_wallet,grounding.huawei,fund.investment,trade.condition,quote.changeV2,trade.lb_condition_mit,share.facebook,trade.commission'
'ip-mainland', 'true'
'x-member-id', ''
'ip-city', 'Dayuan'
'x-timestamp', '1629704821335.842'
'x-trace-id', '846a100d83de4003d07f3c2c822079b4'
'micro-service', 'lb.member.auth'
'accept-encoding', 'gzip'
'sid', ''
'x-api-key', 'ba2fcf22f83637bb835e54ecf5d9c9ae'
'account-open', 'false'
'timeout', '6000000000'
'x-content-type', 'application/json'
'user-region', ''
'x-device-id', 'c367a1101f9ab7a2'
'micro-from-service', 'lb.gateway.api'
'x-user-agent', 'lb/4.0.0(Android;Android 9)'
'x-from-cluster', 'HK-1'
'accept-language', 'zh-CN'
'x-os-version', '9'
'x-channel', 'AO000000'
'x-application-build', '27900'
'x-request-id', '846a100d83de4003d07f3c2c822079b4'
'x-application-version', '4.0.0'
'x-device-name', 'MI 8 SE'
'base-level', '0'
'x-device-model', 'MI 8 SE'
'x-bundle-id', 'global.longbridge.android.debug'
'x-platform', 'android'
'uber-trace-id', '846a100d83de4003d07f3c2c822079b4:3dbf5417b96923f1:1949dcb0bd447abf:1'
'x-real-ip', '118.122.97.128'
'member-id', ''
'x-stage', 'prod'
'micro-endpoint', 'MemberAuth.SendCode'
'market-levels', ''
'x-prefer-language', 'zh-CN'
'x-host', 'api.longbridge.xyz'

2021-08-23T07:47:01.421949Z debug   envoy wasm  wasm filter do decodeHeader
2021-08-23T07:47:01.421959Z trace   envoy wasm  [host->vm] proxy_on_context_create(851827, 1)
2021-08-23T07:47:01.421978Z trace   envoy wasm  [vm->host] env.proxy_get_property(5338064, 19, 5319884, 5319880)
2021-08-23T07:47:01.422000Z trace   envoy wasm  [host->vm] malloc(8)
2021-08-23T07:47:01.422004Z trace   envoy wasm  [host<-vm] malloc return: 5351200
2021-08-23T07:47:01.422006Z trace   envoy wasm  [vm<-host] env.proxy_get_property return: 0
2021-08-23T07:47:01.422009Z trace   envoy wasm  [host<-vm] proxy_on_context_create return: void
2021-08-23T07:47:01.422011Z debug   envoy wasm  wasm done onCreate
2021-08-23T07:47:01.422014Z trace   envoy wasm  [host->vm] proxy_on_request_headers(851827, 48, 0)
2021-08-23T07:47:01.422019Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4966, 24, 5319920, 5319904)
2021-08-23T07:47:01.422024Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-23T07:47:01.422026Z trace   envoy wasm  [vm->host] env.proxy_get_header_map_value(0, 4944, 21, 5319920, 5319904)
2021-08-23T07:47:01.422029Z trace   envoy wasm  [vm<-host] env.proxy_get_header_map_value return: 1
2021-08-23T07:47:01.422034Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4944, 21, 5322240, 904)
2021-08-23T07:47:01.422090Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-23T07:47:01.422099Z trace   envoy wasm  [vm->host] env.proxy_replace_header_map_value(0, 4966, 24, 5325576, 85)
2021-08-23T07:47:01.422103Z trace   envoy wasm  [vm<-host] env.proxy_replace_header_map_value return: 0
2021-08-23T07:47:01.422106Z trace   envoy wasm  [host<-vm] proxy_on_request_headers return: 0
2021-08-23T07:47:01.422110Z trace   envoy http  [C291517][S4289254375588132466] decode headers called: filter=0x563fe52f7d50 status=0
2021-08-23T07:47:01.422118Z debug   envoy filter    override with 3 ALPNs
2021-08-23T07:47:01.422147Z trace   envoy http  [C291517][S4289254375588132466] decode headers called: filter=0x563fe82e9ce0 status=0
2021-08-23T07:47:01.422154Z debug   envoy filter    cors filter do decodeHeader
2021-08-23T07:47:01.422157Z trace   envoy http  [C291517][S4289254375588132466] decode headers called: filter=0x563fe8774d90 status=0
2021-08-23T07:47:01.422160Z debug   envoy filter    fault filter do decodeHeader
2021-08-23T07:47:01.422163Z trace   envoy http  [C291517][S4289254375588132466] decode headers called: filter=0x563fe7f6c0e0 status=0
2021-08-23T07:47:01.422165Z debug   envoy wasm  wasm filter do decodeHeader
2021-08-23T07:47:01.422167Z debug   envoy wasm  wasm done onCreate
2021-08-23T07:47:01.422172Z debug   envoy http  [C291517][S4289254375588132466] doEndStream() resetting stream
2021-08-23T07:47:01.422175Z debug   envoy http  [C291517][S4289254375588132466] stream reset
2021-08-23T07:47:01.422192Z trace   envoy wasm  [host->vm] proxy_on_log(851827)
2021-08-23T07:47:01.422200Z trace   envoy wasm  [host<-vm] proxy_on_log return: void
2021-08-23T07:47:01.422202Z trace   envoy wasm  [host->vm] proxy_on_done(851827)
2021-08-23T07:47:01.422224Z trace   envoy wasm  [host<-vm] proxy_on_done return: 1
2021-08-23T07:47:01.422231Z trace   envoy wasm  [host->vm] proxy_on_delete(851827)
2021-08-23T07:47:01.422234Z trace   envoy wasm  [host<-vm] proxy_on_delete return: void
2021-08-23T07:47:01.422238Z trace   envoy main  item added to deferred deletion list (size=1)
2021-08-23T07:47:01.422244Z trace   envoy http  [C291517][S4289254375588132466] decode headers called: filter=0x563fe82ebc00 status=1
2021-08-23T07:47:01.422249Z trace   envoy http2 [C291517] dispatched 1907 bytes
2021-08-23T07:47:01.422253Z trace   envoy http2 [C291517] about to send frame type=3, flags=0
2021-08-23T07:47:01.422255Z trace   envoy http2 [C291517] send data: bytes=13
2021-08-23T07:47:01.422259Z trace   envoy connection    [C291517] writing 13 bytes, end_stream false
2021-08-23T07:47:01.422263Z trace   envoy http2 [C291517] sent frame type=3
2021-08-23T07:47:01.422266Z debug   envoy http2 [C291517] sent reset code=0
2021-08-23T07:47:01.422268Z debug   envoy http2 [C291517] stream closed: 0

It seems like wasm filter's decodeHeaders function causing reset stream.

I will disable wasm-based telemetry in istio to try again.

Patrick0308 commented 3 years ago

@lizan Through more than ten days of testing after disable wasm-based telemetry, the problem has not reoccured. I will not close this issue, because the issue is not be fixed.

lizan commented 3 years ago

Can you open an issue in Istio side as well to track? This is likely the wasm-based telemery implementation issue.

mathetake commented 3 years ago

ACKed.

github-actions[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.

github-actions[bot] commented 3 years ago

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted" or "no stalebot". Thank you for your contributions.