response flag URX on requests with response_code_details *wasm_fail_stream*
ajohnstone opened this issue · 4 comments
ajohnstone commented
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.
The problem:
- 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.
- When I delete the wasmplugin, response codes return to 200 on all subsequent requests.
- I'm able to reproduce the problem by:
- scaling the workloads to 0
- run a number of requests
- scaling them back to 1 instance
kubectl -n bookinfo scale --replicas=1 deploy productpage-v1 - at this point the only remedy is to delete the wasmplugin.
- health checks succeed whilst URX is returned when in a broken state.
5
Observations when it becomes URX
- It can be intermittent between 200 and 503 URX
- 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
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
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
- request end stream - closing the stream
- Sending local reply with details wasm_fail_stream
- 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
ajohnstone commented
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
Same behaviour described here... if you search for wasm_fail_stream
and same behaviour as envoyproxy/envoy#26485
ajohnstone commented
proxywasm.ReplaceHttpResponseHeader's was causing a panic and segfaulting. I've fixed this within my wasmplugin, as such will close out.