search

tetratelabs / proxy-wasm-go-sdk

WebAssembly for Proxies (Go SDK)
Apache License 2.0
689 stars 152 forks source link

response flag URX on requests with response_code_details *wasm_fail_stream* #372

Closed ajohnstone closed 1 year ago

ajohnstone commented 1 year ago

Describe the bug / error

UPDATE: ingress-gateway succeeds, but envoy proxy downstream observes 3 consecutive fails with wasm_fail_stream.

Appears due to

productpage-v1-7468459577-w8xpk istio-proxy 2023-03-30T21:13:12.686854Z error   envoy wasm      Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
productpage-v1-7468459577-w8xpk istio-proxy Proxy-Wasm plugin in-VM backtrace:
productpage-v1-7468459577-w8xpk istio-proxy   0:  0x1576 - runtime._panic
productpage-v1-7468459577-w8xpk istio-proxy   1:  0x231e4 - (*main.pluginContext).OnTick
productpage-v1-7468459577-w8xpk istio-proxy   2:  0x21b0d - proxy_on_tick

I've recorded my terminal to demonstrate this, as unfortunately issue #369 was closed, with an insufficient description of the problem. It could well be an issue with envoy or with the implementation of the wasmplugin.

See video of issue below. asciicast

The problem:

  1. I'm able to repeatedly get the wasmplugin to end up returning URX when enabled, despite the underlying pod being in a healthy state at the time of execution.
  2. When I delete the wasmplugin, response codes return to 200 on all subsequent requests.
  3. I'm able to reproduce the problem by:
    1. scaling the workloads to 0
    2. run a number of requests
    3. scaling them back to 1 instance kubectl -n bookinfo scale --replicas=1 deploy productpage-v1
    4. at this point the only remedy is to delete the wasmplugin.
  4. health checks succeed whilst URX is returned when in a broken state. 5

Observations when it becomes URX

  1. It can be intermittent between 200 and 503 URX
  2. clusters metric for rq_error increments in 3s. 
    $ k -n istio-system exec -it istio-ingressgateway-7b6ffdff7c-5njpp -- curl -s 0:15000/clusters | grep prod | grep rq_err
outbound|9080|v1|productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::0
outbound|9080||productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::36
$ curl -sSL -w '%{time_total} %{http_code}\n' -o /dev/null 'localhost/productpage' 
0.052602 200
$ k -n istio-system exec -it istio-ingressgateway-7b6ffdff7c-5njpp -- curl -s 0:15000/clusters | grep prod | grep rq_err
outbound|9080|v1|productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::0
outbound|9080||productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::36
$ curl -sSL -w '%{time_total} %{http_code}\n' -o /dev/null 'localhost/productpage' 
0.081538 503
$ k -n istio-system exec -it istio-ingressgateway-7b6ffdff7c-5njpp -- curl -s 0:15000/clusters | grep prod | grep rq_err
outbound|9080|v1|productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::0
outbound|9080||productpage.bookinfo.svc.cluster.local::10.244.0.95:9080::rq_error::39
  3. x-envoy-attempt-count', '1' shows as attempt 1, but rq_error increments in 3's.

example bad response with full trace.

https://gist.github.com/ajohnstone/7d1d4cc4f6d889862c45c6c996725e71

What is your Envoy/Istio version?

1.16.1

What is the SDK version?

v0.21.0

What is your TinyGo version?

tinygo version 0.26.0 darwin/amd64 (using go version go1.19.5 and LLVM version 14.0.0)

ajohnstone commented 1 year ago

any ideas why, or how to fix this?

UPDATE
I've resolved... the following however I'm still able to get the response with wasm_fail_stream.

productpage-v1-7468459577-w8xpk istio-proxy 2023-03-30T21:13:12.686854Z error   envoy wasm      Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
productpage-v1-7468459577-w8xpk istio-proxy Proxy-Wasm plugin in-VM backtrace:
productpage-v1-7468459577-w8xpk istio-proxy   0:  0x1576 - runtime._panic
productpage-v1-7468459577-w8xpk istio-proxy   1:  0x231e4 - (*main.pluginContext).OnTick
productpage-v1-7468459577-w8xpk istio-proxy   2:  0x21b0d - proxy_on_tick
  1. request end stream - closing the stream
  2. Sending local reply with details wasm_fail_stream
  3. The wasm plugin does not look like it has been executed.

productpage-v1-7468459577-447zs istio-proxy 2023-04-01T17:14:22.346079Z debug   envoy http  [C19][S154105690214846718] request end stream
productpage-v1-7468459577-447zs istio-proxy 2023-04-01T17:14:22.346105Z debug   envoy connection    [C19] current connecting state: false
productpage-v1-7468459577-447zs istio-proxy 2023-04-01T17:14:22.346205Z trace   envoy http  [C19][S154105690214846718] decode headers called: filter=istio.metadata_exchange status=0
productpage-v1-7468459577-447zs istio-proxy 2023-04-01T17:14:22.346223Z debug   envoy http  [C19][S154105690214846718] Sending local reply with details wasm_fail_stream
productpage-v1-7468459577-447zs istio-proxy 2023-04-01T17:14:22.346236Z trace   envoy http  [C19][S154105690214846718] encode headers called: filter=istio.stats status=0

https://github.com/envoyproxy/envoy/blob/main/source/extensions/common/wasm/context.cc#LL1576C57-L1576C73

ajohnstone commented 1 year ago

more logs...

productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329915Z trace   envoy http  [C16] onHeadersCompleteBase
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329917Z trace   envoy http  [C16] completed header: key=x-b3-sampled value=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329922Z trace   envoy http  [C16] Server: onHeadersComplete size=15
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329928Z trace   envoy http  [C16] message complete
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329941Z debug   envoy http  [C16][S16958678956284549007] request headers complete (end_stream=true):
productpage-v1-7468459577-df6bh istio-proxy ':authority', 'localhost'
productpage-v1-7468459577-df6bh istio-proxy ':path', '/productpage'
productpage-v1-7468459577-df6bh istio-proxy ':method', 'GET'
productpage-v1-7468459577-df6bh istio-proxy 'user-agent', 'curl/7.85.0'
productpage-v1-7468459577-df6bh istio-proxy 'accept', '*/*'
productpage-v1-7468459577-df6bh istio-proxy 'andy', '1'
productpage-v1-7468459577-df6bh istio-proxy 'x-forwarded-for', '10.244.0.1'
productpage-v1-7468459577-df6bh istio-proxy 'x-forwarded-proto', 'http'
productpage-v1-7468459577-df6bh istio-proxy 'x-envoy-internal', 'true'
productpage-v1-7468459577-df6bh istio-proxy 'x-request-id', '7d801cd9-4875-49f9-b8ba-b78188e386b2'
productpage-v1-7468459577-df6bh istio-proxy 'x-envoy-decorator-operation', 'productpage.bookinfo.svc.cluster.local:9080/productpage'
productpage-v1-7468459577-df6bh istio-proxy 'x-envoy-peer-metadata', 'ChQKDkFQUF9DT05UQUlORVJTEgIaAAoaCgpDTFVTVEVSX0lEEgwaCkt1YmVybmV0ZXMKHgoMSU5TVEFOQ0VfSVBTEg4aDDEwLjI0NC4wLjExNAoZCg1JU1RJT19WRVJTSU9OEggaBjEuMTYuMQqcAwoGTEFCRUxTEpEDKo4DCh0KA2FwcBIWGhRpc3Rpby1pbmdyZXNzZ2F0ZXdheQoTCgVjaGFydBIKGghnYXRld2F5cwoUCghoZXJpdGFnZRIIGgZUaWxsZXIKNgopaW5zdGFsbC5vcGVyYXRvci5pc3Rpby5pby9vd25pbmctcmVzb3VyY2USCRoHdW5rbm93bgoZCgVpc3RpbxIQGg5pbmdyZXNzZ2F0ZXdheQoZCgxpc3Rpby5pby9yZXYSCRoHZGVmYXVsdAowChtvcGVyYXRvci5pc3Rpby5pby9jb21wb25lbnQSERoPSW5ncmVzc0dhdGV3YXlzChIKB3JlbGVhc2USBxoFaXN0aW8KOQofc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtbmFtZRIWGhRpc3Rpby1pbmdyZXNzZ2F0ZXdheQovCiNzZXJ2aWNlLmlzdGlvLmlvL2Nhbm9uaWNhbC1yZXZpc2lvbhIIGgZsYXRlc3QKIgoXc2lkZWNhci5pc3Rpby5pby9pbmplY3QSBxoFZmFsc2UKGgoHTUVTSF9JRBIPGg1jbHVzdGVyLmxvY2FsCi8KBE5BTUUSJxolaXN0aW8taW5ncmVzc2dhdGV3YXktN2I2ZmZkZmY3Yy1kdnZicAobCglOQU1FU1BBQ0USDhoMaXN0aW8tc3lzdGVtCl0KBU9XTkVSElQaUmt1YmVybmV0ZXM6Ly9hcGlzL2FwcHMvdjEvbmFtZXNwYWNlcy9pc3Rpby1zeXN0ZW0vZGVwbG95bWVudHMvaXN0aW8taW5ncmVzc2dhdGV3YXkKFwoRUExBVEZPUk1fTUVUQURBVEESAioACicKDVdPUktMT0FEX05BTUUSFhoUaXN0aW8taW5ncmVzc2dhdGV3YXk='
productpage-v1-7468459577-df6bh istio-proxy 'x-envoy-peer-metadata-id', 'router~10.244.0.114~istio-ingressgateway-7b6ffdff7c-dvvbp.istio-system~istio-system.svc.cluster.local'
productpage-v1-7468459577-df6bh istio-proxy 'x-envoy-attempt-count', '3'
productpage-v1-7468459577-df6bh istio-proxy 'x-b3-traceid', 'bb9f48ae17b956d97225fb9291b4509f'
productpage-v1-7468459577-df6bh istio-proxy 'x-b3-spanid', '7225fb9291b4509f'
productpage-v1-7468459577-df6bh istio-proxy 'x-b3-sampled', '0'
productpage-v1-7468459577-df6bh istio-proxy
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.329950Z debug   envoy http  [C16][S16958678956284549007] request end stream
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330038Z debug   envoy connection    [C16] current connecting state: false
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330202Z trace   envoy http  [C16][S16958678956284549007] decode headers called: filter=istio.metadata_exchange status=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330212Z debug   envoy http  [C16][S16958678956284549007] Sending local reply with details wasm_fail_stream
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330224Z trace   envoy http  [C16][S16958678956284549007] encode headers called: filter=istio.stats status=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330226Z trace   envoy http  [C16][S16958678956284549007] encode headers called: filter=envoy.filters.http.cors status=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330228Z trace   envoy http  [C16][S16958678956284549007] encode headers called: filter=envoy.filters.http.fault status=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330230Z debug   envoy http  [C16][S16958678956284549007] Sending local reply with details wasm_fail_stream directly to the encoder
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330245Z debug   envoy http  [C16][S16958678956284549007] encoding headers via codec (end_stream=true):
productpage-v1-7468459577-df6bh istio-proxy ':status', '503'
productpage-v1-7468459577-df6bh istio-proxy 'date', 'Sat, 01 Apr 2023 17:31:26 GMT'
productpage-v1-7468459577-df6bh istio-proxy 'server', 'istio-envoy'
productpage-v1-7468459577-df6bh istio-proxy
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330295Z trace   envoy connection    [C16] writing 113 bytes, end_stream false
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330303Z trace   envoy main  item added to deferred deletion list (size=1)
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330604Z debug   envoy wasm  wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:677]::report() metricKey cache hit , stat=16
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330654Z debug   envoy wasm  wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:677]::report() metricKey cache hit , stat=18
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330659Z debug   envoy wasm  wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:677]::report() metricKey cache hit , stat=22
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330662Z debug   envoy wasm  wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:677]::report() metricKey cache hit , stat=26
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330670Z trace   envoy main  item added to deferred deletion list (size=2)
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330675Z trace   envoy misc  enableTimer called on 0x55f396c15400 for 3600000ms, min is 3600000ms
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330682Z trace   envoy http  [C16][S16958678956284549007] encode headers called: filter=istio-system.wasm-headers-go status=4
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330686Z trace   envoy http  [C16][S16958678956284549007] decodeHeaders filter iteration aborted due to local reply: filter=istio-system.wasm-headers-go
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330688Z trace   envoy http  [C16][S16958678956284549007] decode headers called: filter=istio-system.wasm-headers-go status=1
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330694Z trace   envoy http  [C16] parsed 1641 bytes
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330701Z trace   envoy main  clearing deferred deletion list (size=2)
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330722Z trace   envoy connection    [C16] socket event: 2
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330730Z trace   envoy connection    [C16] write ready
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:27.330836Z trace   envoy connection    [C16] ssl write returns: 113
productpage-v1-7468459577-df6bh istio-proxy {"downstream_local_address":"10.244.0.115:9080","bytes_sent":0,"upstream_local_address":null,"bytes_received":0,"upstream_transport_failure_reason":null,"x_forwarded_for":"10.244.0.1","requested_server_name":"outbound_.9080_._.productpage.bookinfo.svc.cluster.local","request_id":"7d801cd9-4875-49f9-b8ba-b78188e386b2","duration":1,"response_code_details":"wasm_fail_stream","user_agent":"curl/7.85.0","route_name":null,"downstream_remote_address":"10.244.0.1:0","start_time":"2023-04-01T17:31:27.296Z","upstream_host":null,"response_code":503,"path":"/productpage","response_flags":"-","upstream_service_time":null,"connection_termination_details":null,"authority":"localhost","method":"GET","upstream_cluster":"inbound|9080||","protocol":"HTTP/1.1"}
productpage-v1-7468459577-df6bh istio-proxy {"duration":0,"protocol":"HTTP/1.1","user_agent":"curl/7.85.0","upstream_cluster":"inbound|9080||","requested_server_name":"outbound_.9080_._.productpage.bookinfo.svc.cluster.local","downstream_local_address":"10.244.0.115:9080","response_code":503,"response_flags":"-","route_name":null,"upstream_transport_failure_reason":null,"connection_termination_details":null,"upstream_service_time":null,"path":"/productpage","bytes_received":0,"start_time":"2023-04-01T17:31:27.313Z","upstream_host":null,"request_id":"7d801cd9-4875-49f9-b8ba-b78188e386b2","response_code_details":"wasm_fail_stream","downstream_remote_address":"10.244.0.1:0","x_forwarded_for":"10.244.0.1","bytes_sent":0,"method":"GET","upstream_local_address":null,"authority":"localhost"}
productpage-v1-7468459577-df6bh istio-proxy {"upstream_cluster":"inbound|9080||","start_time":"2023-04-01T17:31:27.329Z","bytes_received":0,"user_agent":"curl/7.85.0","upstream_local_address":null,"response_code":503,"requested_server_name":"outbound_.9080_._.productpage.bookinfo.svc.cluster.local","duration":0,"path":"/productpage","upstream_transport_failure_reason":null,"authority":"localhost","response_flags":"-","downstream_remote_address":"10.244.0.1:0","method":"GET","upstream_host":null,"x_forwarded_for":"10.244.0.1","response_code_details":"wasm_fail_stream","upstream_service_time":null,"downstream_local_address":"10.244.0.115:9080","route_name":null,"request_id":"7d801cd9-4875-49f9-b8ba-b78188e386b2","bytes_sent":0,"protocol":"HTTP/1.1","connection_termination_details":null}
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055018Z trace   envoy misc  enableTimer called on 0x55f395ead080 for 3600000ms, min is 3600000ms
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055094Z debug   envoy conn_handler  [C85] new connection from 10.244.0.1:44834
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055116Z trace   envoy connection    [C85] socket event: 3
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055120Z trace   envoy connection    [C85] write ready
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055124Z trace   envoy connection    [C85] read ready. dispatch_buffered_data=0
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055136Z trace   envoy connection    [C85] read returns: 118
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055146Z trace   envoy connection    [C85] read error: Resource temporarily unavailable
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055162Z trace   envoy http  [C85] parsing 118 bytes
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055166Z trace   envoy http  [C85] message begin
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055173Z debug   envoy http  [C85] new stream
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055182Z trace   envoy misc  enableTimer called on 0x55f395ead200 for 300000ms, min is 300000ms
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055194Z trace   envoy http  [C85] completed header: key=Host value=10.244.0.115:15021
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055248Z trace   envoy http  [C85] completed header: key=User-Agent value=kube-probe/1.25
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055257Z trace   envoy http  [C85] completed header: key=Accept value=*/*
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055262Z trace   envoy http  [C85] onHeadersCompleteBase
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055264Z trace   envoy http  [C85] completed header: key=Connection value=close
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055271Z trace   envoy http  [C85] Server: onHeadersComplete size=4
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055279Z trace   envoy http  [C85] message complete
productpage-v1-7468459577-df6bh istio-proxy 2023-04-01T17:31:28.055289Z debug   envoy http  [C85][S17481804434879356675] request headers complete (end_stream=true):
ajohnstone commented 1 year ago

Same behaviour described here... if you search for wasm_fail_stream and same behaviour as https://github.com/envoyproxy/envoy/issues/26485

https://webthesis.biblio.polito.it/21170/1/tesi.pdf

image
ajohnstone commented 1 year ago

proxywasm.ReplaceHttpResponseHeader's was causing a panic and segfaulting. I've fixed this within my wasmplugin, as such will close out.