Istio 1.5 Ingress Gateway Proxy Crash

arei · May 9, 2020, 6:29pm

Hi,

We’re having a problem with the IngressGateway Envoy Proxy crashing regularly on incoming requests when our custom lua filter is applied in a particular order (running Istio 1.5.1). The lua filter (which does redirect and handles authn callback) must be after both of the envoy.filters.http.wasm filters (envoy.wasm.metadata_exchange, and envoy.wasm.stats) or the ingress envoy proxy will crash every few requests.

Not really sure what’s causing the crash, but it’s very consistent and goes away when removing and reapplying the Envoy Filter, which causes it to be applied in a different order.

Unfortunately, since Envoy doesn’t give us much control over the ordering (and we’re doing declarative deployments via Flux) we’re having trouble getting around this without being very hacky. Even when using the subfilter and INSERT_AFTER, the lua filter ends up between the two wasm filters (presumably since they’re named the same).

It seems there’s an unhandled exception here somewhere, but it’s really hard to pinpoint… See backtrace below.

Has anyone seen something similar? Any advice on narrowing the problem down more?

Also, it would be really nice to be able to make the filter order deterministic. If I’m right about the WASM filter naming getting in the way, do we need (or already have?) a different mechanism to specify filter order rather than name?

Here’s the backtrace from the crash:

2020-05-07T09:59:48.979281Z info No more active epochs, terminating
2020-05-07T09:59:48.979266Z error Epoch 0 exited with error: signal: aborted (core dumped)
2020-05-07T09:59:48.978645Z error sds Remote side closed connection
2020-05-07T09:59:48.978538Z info sds node:router~10.1.0.115~istio-ingressgateway-598df4fd84-hc6gb.istio-system~istio-system.svc.cluster.local-1 resource:ROOTCA connection is terminated: rpc error: code = Canceled desc = context canceled
2020-05-07T09:59:48.978508Z info transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-05-07T09:59:48.978498Z error sds Remote side closed connection
2020-05-07T09:59:48.978467Z info sds node:router~10.1.0.115~istio-ingressgateway-598df4fd84-hc6gb.istio-system~istio-system.svc.cluster.local-2 resource:default connection is terminated: rpc error: code = Canceled desc = context canceled
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #23: start_thread [0x7f4b31c346db]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #22: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x56048ac43f53]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #21: Envoy::Server::WorkerImpl::threadRoutine() [0x56048a73d818]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #20: event_base_loop [0x56048aa7781e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #19: event_process_active_single_queue [0x56048aa78f8b]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #18: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x56048a747b90]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #17: Envoy::Network::ConnectionImpl::onFileEvent() [0x56048a74d0bd]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #16: Envoy::Network::ConnectionImpl::onReadReady() [0x56048a74d5ea]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #15: Envoy::Network::FilterManagerImpl::onContinueReading() [0x56048a750b7b]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #14: Envoy::Http::ConnectionManagerImpl::onData() [0x56048a992451]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #13: Envoy::Http::Http2::ServerConnectionImpl::dispatch() [0x56048a9b4730]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #12: Envoy::Http::Http2::ConnectionImpl::dispatch() [0x56048a9b0ad9]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #11: nghttp2_session_mem_recv [0x56048aa019fa]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #10: nghttp2_session_on_rst_stream_received [0x56048a9fe771]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #9: nghttp2_session_close_stream [0x56048a9fba67]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #8: Envoy::Http::Http2::ConnectionImpl::Http2Callbacks::Http2Callbacks()::$_12::__invoke() [0x56048a9b598c]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #7: Envoy::Http::Http2::ConnectionImpl::onStreamClose() [0x56048a9b250e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #6: Envoy::Http::ConnectionManagerImpl::ActiveStream::onResetStream() [0x56048a99b919]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #5: Envoy::Http::ConnectionManagerImpl::doDeferredStreamDestroy() [0x56048a991c3e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #4: Envoy::Extensions::Common::Wasm::Context::onDone() [0x560489a0fff7]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #3: std::__1::__function::__func<>::operator()() [0x56048931b628]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #2: std::__terminate() [0x56048b171073]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.823][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:77] #1: [0x56048ac0e2b9]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #0: __restore_rt [0x7f4b31c3f890]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:71] Envoy version: 6cdd2c56746ef582c8a851ed234c71719f9e3742/1.13.1-dev/Clean/RELEASE/BoringSSL
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:70] Backtrace (use tools/stack_decode.py to get line numbers):
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:83] Caught Aborted, suspect faulting address 0x10
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #23: start_thread [0x7f4b31c346db]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.808][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #22: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x56048ac43f53]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.792][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #21: Envoy::Server::WorkerImpl::threadRoutine() [0x56048a73d818]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.773][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #20: event_base_loop [0x56048aa7781e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.755][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #19: event_process_active_single_queue [0x56048aa78f8b]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.738][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #18: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x56048a747b90]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.727][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #17: Envoy::Network::ConnectionImpl::onFileEvent() [0x56048a74d0bd]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.713][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #16: Envoy::Network::ConnectionImpl::onReadReady() [0x56048a74d5ea]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.701][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #15: Envoy::Network::FilterManagerImpl::onContinueReading() [0x56048a750b7b]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.688][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #14: Envoy::Http::ConnectionManagerImpl::onData() [0x56048a992451]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.676][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #13: Envoy::Http::Http2::ServerConnectionImpl::dispatch() [0x56048a9b4730]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.663][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #12: Envoy::Http::Http2::ConnectionImpl::dispatch() [0x56048a9b0ad9]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.650][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #11: nghttp2_session_mem_recv [0x56048aa019fa]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.638][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #10: nghttp2_session_on_rst_stream_received [0x56048a9fe771]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.627][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #9: nghttp2_session_close_stream [0x56048a9fba67]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.614][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #8: Envoy::Http::Http2::ConnectionImpl::Http2Callbacks::Http2Callbacks()::$_12::__invoke() [0x56048a9b598c]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.601][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #7: Envoy::Http::Http2::ConnectionImpl::onStreamClose() [0x56048a9b250e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.587][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #6: Envoy::Http::ConnectionManagerImpl::ActiveStream::onResetStream() [0x56048a99b919]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.575][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #5: Envoy::Http::ConnectionManagerImpl::doDeferredStreamDestroy() [0x56048a991c3e]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.564][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #4: Envoy::Extensions::Common::Wasm::Context::onDone() [0x560489a0fff7]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.553][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #3: std::__1::__function::__func<>::operator()() [0x56048931b628]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.543][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #2: std::__terminate() [0x56048b171073]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.533][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:77] #1: [0x56048ac0e2b9]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.517][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #0: Envoy::TerminateHandler::logOnTerminate()::$_0::operator()() [0x56048ac0e3ae]
[Envoy (Epoch 0)] [2020-05-07 09:59:48.502][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:71] Envoy version: 6cdd2c56746ef582c8a851ed234c71719f9e3742/1.13.1-dev/Clean/RELEASE/BoringSSL
[Envoy (Epoch 0)] [2020-05-07 09:59:48.502][26][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:70] Backtrace (use tools/stack_decode.py to get line numbers):
[Envoy (Epoch 0)] [2020-05-07 09:59:48.502][26][critical][main] [external/envoy/source/exe/terminate_handler.cc:13] std::terminate called! (possible uncaught exception, see trace)
[2020-05-07T09:59:48.011Z] "GET /Apis HTTP/2" 200 - "-" "-" 0 4924 126 - "10.1.1.250" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:76.0) Gecko/20100101 Firefox/76.0" ...
2020-05-07T09:59:37.301075Z info Envoy proxy is ready

Thanks.

arei · May 11, 2020, 6:38pm

This seems to be more widespread than I originally thought. Even after temporarily working around the problem at the ingressgateway level, we’re having very similar problems with pods with opa-istio applied (which also creates an envoy.ext_authz filter). The crash is less frequent - and maybe only be with multiple concurrent requests, but it’s still very common. In this case it doesn’t seem to make a difference what order the filters are applied in though. Once again, from the backtrace, this appears to be in the wasm onDone. We have confirmed the same behavior in Istio 1.5.2.

[Envoy (Epoch 0)] [2020-05-11 14:53:05.559][23][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:104] [C1101] using existing connection
[Envoy (Epoch 0)] [2020-05-11 14:53:05.559][23][debug][router] [external/envoy/source/common/router/router.cc:1711] [C1159][S1228942189900616082] pool ready
[Envoy (Epoch 0)] [2020-05-11 14:53:05.560][23][debug][grpc] [external/envoy/source/common/grpc/google_async_client_impl.cc:379] Stream cleanup with 0 in-flight tags
[Envoy (Epoch 0)] [2020-05-11 14:53:05.560][23][debug][grpc] [external/envoy/source/common/grpc/google_async_client_impl.cc:368] Deferred delete
[Envoy (Epoch 0)] [2020-05-11 14:53:05.561][23][debug][grpc] [external/envoy/source/common/grpc/google_async_client_impl.cc:145] GoogleAsyncStreamImpl destruct
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:77] #1: [0x55a419f8d2b9]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #2: std::__terminate() [0x55a41a4f0073]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #3: std::__1::__function::__func<>::operator()() [0x55a41869a628]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #4: Envoy::Extensions::Common::Wasm::Context::onDone() [0x55a418d8eff7]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #5: Envoy::Http::ConnectionManagerImpl::doDeferredStreamDestroy() [0x55a419d10c3e]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #6: Envoy::Http::ConnectionManagerImpl::ActiveStream::onResetStream() [0x55a419d1a919]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #7: Envoy::Http::ConnectionManagerImpl::resetAllStreams() [0x55a419d11223]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #8: Envoy::Network::ConnectionImplBase::raiseConnectionEvent() [0x55a419acf02d]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #9: Envoy::Network::ConnectionImpl::raiseEvent() [0x55a419acb212]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #10: Envoy::Network::ConnectionImpl::closeSocket() [0x55a419acacd8]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #11: Envoy::Network::ConnectionImpl::onReadReady() [0x55a419acc6b2]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #12: Envoy::Network::ConnectionImpl::onFileEvent() [0x55a419acc0bd]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #13: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x55a419ac6b90]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #14: event_process_active_single_queue [0x55a419df7f8b]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #15: event_base_loop [0x55a419df681e]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.574][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #16: Envoy::Server::WorkerImpl::threadRoutine() [0x55a419abc818]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.575][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #17: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x55a419fc2f53]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.575][24][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #18: start_thread [0x7f109b0ec6db]
[Envoy (Epoch 0)] [2020-05-11 14:53:05.575][23][debug][filter] [external/envoy/source/extensions/filters/listener/original_dst/original_dst.cc:18] original_dst: New connection accepted
2020-05-11T14:53:05.792862Z	info	sds	node:sidecar~10.1.1.187~eco-portal-prod-54d98ccbdb-bhtjx.ecosystem-prod~ecosystem-prod.svc.cluster.local-1 resource:ROOTCA connection is terminated: rpc error: code = Canceled desc = context canceled
2020-05-11T14:53:05.792895Z	error	sds	Remote side closed connection
2020-05-11T14:53:05.792941Z	info	transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-05-11T14:53:05.801615Z	error	Epoch 0 exited with error: signal: aborted (core dumped)
2020-05-11T14:53:05.802136Z	info	No more active epochs, terminating

liuck · May 15, 2020, 8:32am

I have same problem,

github.com/istio/istio

Istio 1.5 Ingress Gateway Proxy Crash when custom lua filter is applied

opened 03:25AM - 15 May 20 UTC

closed 03:40AM - 18 May 20 UTC

lck0129

area/perf and scalability

**Bug description** We’re having a problem with the IngressGateway Envoy Prox…y crashing regularly on incoming requests when our custom lua filter is applied in a particular order (running Istio 1.5.0). **Steps to reproduce the bug** **keep pressing F5** to refresh the web browser after apply below lua scritps on ingress gateway: apiVersion: networking.istio.io/v1alpha3 kind: EnvoyFilter metadata: name: edge-lua-filter namespace: istio-system spec: workloadLabels: app: istio-ingressgateway configPatches: - applyTo: LISTENER ListenerMatch: 0.0.0.0_8080 patch: operation: MERGE value: per_connection_buffer_limit_bytes: 100000000 filters: - listenerMatch: listenerType: GATEWAY filterName: envoy.lua filterType: HTTP filterConfig: inlineCode: | function version() return "v1" end function log(handle, value) handle:logWarn(version() .. ": " .. value) end -- dump a lua object into a string for logging function dump(o) if type(o) == 'table' then local s = '{ ' for k,v in pairs(o) do if type(k) ~= 'number' then k = '"'..k..'"' end s = s .. '['..k..'] = ' .. dump(v) .. ',' end return s .. '} ' else return tostring(o) end end function get_header(handle, header) return handle:headers():get(header) end function string.starts(String, Start) return string.sub(String, 1, string.len(Start)) == Start end function string.ends(String, End) return End == "" or string.sub(String, -string.len(End)) == End end function envoy_on_request(request_handle) path = get_header(request_handle, ":path") local host = get_header(request_handle, ":authority") -- this is to avoid login going through auth service if path == '/login' or host == 'dont.abc.com' then do return end end -- for /api going through auth service -- if string.starts(path, "/api/") and host == 'app-alpha.abc.com' then if string.starts(path, "/api/") then log(request_handle, "==========START DISPLAYING REQUEST HEADERS") local log_headers = request_handle:headers() for key, value in pairs(log_headers) do log(request_handle, "header key: " .. dump(key) .. ", header value: " .. dump(value)) end log(request_handle, "==========END DISPLAYING REQUEST HEADERS") -- Build a request for our authenticaiton service before passing request upstream local auth_host = "authentication.default.svc.cluster.local" local auth_path = "/authentication/nginx/abc/auth" local cluster = "outbound|80||" .. auth_host local request_headers = { [":method"] = "GET", [":path"] = auth_path, [":authority"] = host, ["token"] = get_header(request_handle, "token"), ["os"] = get_header(request_handle, "os"), ["device"] = get_header(request_handle, "device"), ["User-Agent"] = get_header(request_handle, "user-agent"), ["X-Original-URI"] = path, ["requestId"] = get_header(request_handle, "requestid"), ["menu"] = get_header(request_handle, "menu"), ["pointMenu"] = get_header(request_handle, "pointmenu"), ["userId"] = get_header(request_handle, "userid"), -- for app ["appversion"] = get_header(request_handle, "appversion"), ["workstation"] = get_header(request_handle, "workstation") } local request_body = "" local timeout = 5000 --ms log(request_handle, "Sending auth request, headers: " .. dump(request_headers) .. ", cluster: " .. cluster .. ", request_body: " .. request_body .. ", path: " .. path) log(request_handle, "Sending request to auth service now") response_headers, response_body = request_handle:httpCall( tostring(cluster), request_headers, request_body, timeout ) log(request_handle, "Received response from auth service now") log(request_handle, "response_headers: " .. dump(response_headers)) log(request_handle, "response_body: " .. response_body) -- If the response isn't 200, reject the request if tonumber(response_headers[":status"]) ~= 200 then log(request_handle, "-------------Authentication Failed-----------") request_handle:respond( {[":status"] = response_headers[":status"]}, response_body ) do return end else -- end -- if tonumber(response_headers[":status"]) == 200 then log(request_handle, "----------Authentication Successed----------") local json = require 'cjson' local jsondata = json.decode(response_body) log(request_handle, jsondata.data.userId) end end end function envoy_on_response(response_handle) -- log(response_handle, "response updated from auth service") end **Version (include the output of `istioctl version --remote` and `kubectl version` and `helm version` if you used Helm)** [root@k8s ~]# istioctl version --remote client version: 1.5.0 control plane version: 1.5.0 data plane version: 1.5.0 (64 proxies) [root@k8s ~]# kubectl version Client Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.2", GitCommit:"c97fe5036ef3df2967d086711e6c0c405941e14b", GitTreeState:"clean", BuildDate:"2019-10-15T19:18:23Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"} Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.2", GitCommit:"c97fe5036ef3df2967d086711e6c0c405941e14b", GitTreeState:"clean", BuildDate:"2019-10-15T19:09:08Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"} **How was Istio installed?** **Environment where bug was observed (cloud vendor, OS, etc)** CentOS Linux release 7.7.1908 (Core) Here’s the backtrace from the crash: [Envoy (Epoch 0)] [2020-05-13 10:48:57.260][29][warning][lua] [external/envoy/source/extensions/filters/http/lua/lua_filter.cc:597] script log: v1: Sending request to auth service now [Envoy (Epoch 0)] [2020-05-13 10:48:57.505][29][critical][main] [external/envoy/source/exe/terminate_handler.cc:13] std::terminate called! (possible uncaught exception, see trace) [Envoy (Epoch 0)] [2020-05-13 10:48:57.505][29][critical][backtrace] :70] Backtrace (use tools/stack_decode.py to get line numbers): [Envoy (Epoch 0)] [2020-05-13 10:48:57.505][29][critical][backtrace] :71] Envoy version: 73f240a29bece92a8882a36893ccce07b4a54664/1.13.1-dev/Clean/RELEASE/BoringSSL [Envoy (Epoch 0)] [2020-05-13 10:48:57.529][29][critical][backtrace] :75] #0: Envoy::TerminateHandler::logOnTerminate()::$_0::operator()() [0x56538f0f1dae] [Envoy (Epoch 0)] [2020-05-13 10:48:57.539][29][critical][backtrace] :77] #1: [0x56538f0f1cb9] [Envoy (Epoch 0)] [2020-05-13 10:48:57.550][29][critical][backtrace] :75] #2: std::__terminate() [0x56538f654a73] [Envoy (Epoch 0)] [2020-05-13 10:48:57.561][29][critical][backtrace] :75] #3: std::__1::__function::__func<>::operator()() [0x56538d7ff728] [Envoy (Epoch 0)] [2020-05-13 10:48:57.572][29][critical][backtrace] :75] #4: Envoy::Extensions::Common::Wasm::Context::onDone() [0x56538def3a67] [Envoy (Epoch 0)] [2020-05-13 10:48:57.582][29][critical][backtrace] :75] #5: Envoy::Http::ConnectionManagerImpl::doDeferredStreamDestroy() [0x56538ee7569e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.592][29][critical][backtrace] :75] #6: Envoy::Http::ConnectionManagerImpl::ActiveStream::onResetStream() [0x56538ee7f339] [Envoy (Epoch 0)] [2020-05-13 10:48:57.601][29][critical][backtrace] :75] #7: Envoy::Http::Http2::ConnectionImpl::onStreamClose() [0x56538ee95f2e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.611][29][critical][backtrace] :75] #8: Envoy::Http::Http2::ConnectionImpl::Http2Callbacks::Http2Callbacks()::$_12::__invoke() [0x56538ee993ac] [Envoy (Epoch 0)] [2020-05-13 10:48:57.621][29][critical][backtrace] :75] #9: nghttp2_session_close_stream [0x56538eedf487] [Envoy (Epoch 0)] [2020-05-13 10:48:57.632][29][critical][backtrace] :75] #10: nghttp2_session_on_rst_stream_received [0x56538eee2191] [Envoy (Epoch 0)] [2020-05-13 10:48:57.642][29][critical][backtrace] :75] #11: nghttp2_session_mem_recv [0x56538eee541a] [Envoy (Epoch 0)] [2020-05-13 10:48:57.652][29][critical][backtrace] :75] #12: Envoy::Http::Http2::ConnectionImpl::dispatch() [0x56538ee944f9] [Envoy (Epoch 0)] [2020-05-13 10:48:57.662][29][critical][backtrace] :75] #13: Envoy::Http::Http2::ServerConnectionImpl::dispatch() [0x56538ee98150] [Envoy (Epoch 0)] [2020-05-13 10:48:57.672][29][critical][backtrace] :75] #14: Envoy::Http::ConnectionManagerImpl::onData() [0x56538ee75eb1] [Envoy (Epoch 0)] [2020-05-13 10:48:57.686][29][critical][backtrace] :75] #15: Envoy::Network::FilterManagerImpl::onContinueReading() [0x56538ec345db] [Envoy (Epoch 0)] [2020-05-13 10:48:57.696][29][critical][backtrace] :75] #16: Envoy::Network::ConnectionImpl::onReadReady() [0x56538ec3104a] [Envoy (Epoch 0)] [2020-05-13 10:48:57.705][29][critical][backtrace] :75] #17: Envoy::Network::ConnectionImpl::onFileEvent() [0x56538ec30b1d] [Envoy (Epoch 0)] [2020-05-13 10:48:57.716][29][critical][backtrace] :75] #18: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x56538ec2b5f0] [Envoy (Epoch 0)] [2020-05-13 10:48:57.727][29][critical][backtrace] :75] #19: event_process_active_single_queue [0x56538ef5c9ab] [Envoy (Epoch 0)] [2020-05-13 10:48:57.739][29][critical][backtrace] :75] #20: event_base_loop [0x56538ef5b23e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.752][29][critical][backtrace] :75] #21: Envoy::Server::WorkerImpl::threadRoutine() [0x56538ec21278] [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :75] #22: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x56538f127953] [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :75] #23: start_thread [0x7fc1fc69b6db] [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :83] Caught Aborted, suspect faulting address 0x13 [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :70] Backtrace (use tools/stack_decode.py to get line numbers): [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :71] Envoy version: 73f240a29bece92a8882a36893ccce07b4a54664/1.13.1-dev/Clean/RELEASE/BoringSSL [Envoy (Epoch 0)] [2020-05-13 10:48:57.763][29][critical][backtrace] :75] #0: __restore_rt [0x7fc1fc6a6890] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :77] #1: [0x56538f0f1cb9] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #2: std::__terminate() [0x56538f654a73] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #3: std::__1::__function::__func<>::operator()() [0x56538d7ff728] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #4: Envoy::Extensions::Common::Wasm::Context::onDone() [0x56538def3a67] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #5: Envoy::Http::ConnectionManagerImpl::doDeferredStreamDestroy() [0x56538ee7569e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #6: Envoy::Http::ConnectionManagerImpl::ActiveStream::onResetStream() [0x56538ee7f339] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #7: Envoy::Http::Http2::ConnectionImpl::onStreamClose() [0x56538ee95f2e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #8: Envoy::Http::Http2::ConnectionImpl::Http2Callbacks::Http2Callbacks()::$_12::__invoke() [0x56538ee993ac] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #9: nghttp2_session_close_stream [0x56538eedf487] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #10: nghttp2_session_on_rst_stream_received [0x56538eee2191] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #11: nghttp2_session_mem_recv [0x56538eee541a] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #12: Envoy::Http::Http2::ConnectionImpl::dispatch() [0x56538ee944f9] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #13: Envoy::Http::Http2::ServerConnectionImpl::dispatch() [0x56538ee98150] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #14: Envoy::Http::ConnectionManagerImpl::onData() [0x56538ee75eb1] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #15: Envoy::Network::FilterManagerImpl::onContinueReading() [0x56538ec345db] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #16: Envoy::Network::ConnectionImpl::onReadReady() [0x56538ec3104a] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #17: Envoy::Network::ConnectionImpl::onFileEvent() [0x56538ec30b1d] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #18: Envoy::Event::FileEventImpl::assignEvents()::$_0::__invoke() [0x56538ec2b5f0] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #19: event_process_active_single_queue [0x56538ef5c9ab] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #20: event_base_loop [0x56538ef5b23e] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #21: Envoy::Server::WorkerImpl::threadRoutine() [0x56538ec21278] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #22: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x56538f127953] [Envoy (Epoch 0)] [2020-05-13 10:48:57.774][29][critical][backtrace] :75] #23: start_thread [0x7fc1fc69b6db] 2020-05-13T10:48:57.829396Z info sds node:router~10.244.2.64~istio-ingressgateway-6c447bd5db-j2phk.istio-system~istio-system.svc.cluster.local-2 resource:ROOTCA connection is terminated: rpc error: code = Canceled desc = context canceled 2020-05-13T10:48:57.829451Z error sds Remote side closed connection 2020-05-13T10:48:57.829699Z info transport: loopyWriter.run returning. connection error: desc = "transport is closing" 2020-05-13T10:48:57.829942Z info sds node:router~10.244.2.64~istio-ingressgateway-6c447bd5db-j2phk.istio-system~istio-system.svc.cluster.local-1 resource:default connection is terminated: rpc error: code = Canceled desc = context canceled 2020-05-13T10:48:57.829954Z error sds Remote side closed connection 2020-05-13T10:48:57.830887Z error Epoch 0 exited with error: signal: aborted (core dumped) 2020-05-13T10:48:57.830917Z info No more active epochs, terminating [Uploading istio-dump.tar.gz…]()

arei · May 15, 2020, 4:55pm

I haven’t been able to replicate this (either case describe above) after updating to 1.5.4. Are you able to try that?

liuck · May 16, 2020, 2:29am

Great! thanks for your information.
istio gw is good with1.5.4

Topic		Replies	Views
Has anyone been able to use envoy filters with Lua functions with Istio 1.6.2	2	1778	September 10, 2020
Problems create lua filter Security	3	816	June 2, 2020
Envoy filter failure	4	2726	April 2, 2020
Lua filter istio 1.4	0	572	April 6, 2020
With Istio-1.3 the envoyFilter for external-Auth (INBOUND) doesn't work Networking	0	623	October 7, 2019

Istio 1.5 Ingress Gateway Proxy Crash

Related Topics