envoy
envoy copied to clipboard
debug assertion failure: `assert failure: isIdleImpl()`
Title: debug assertion failure: assert failure: isIdleImpl()
Description: In our CI with debug builds, we are regularly seeing this assertion failure.
2022-08-04T22:11:20.554576Z critical envoy assert assert failure: isIdleImpl().
2022-08-04T22:11:20.554714Z critical envoy backtrace Caught Aborted, suspect faulting address 0x53900000018
2022-08-04T22:11:20.554729Z critical envoy backtrace Backtrace (use tools/stack_decode.py to get line numbers):
2022-08-04T22:11:20.554739Z critical envoy backtrace Envoy version: 01baf88a8942c273181c830b4307bfe70bd839c0/1.24.0-dev/Clean/DEBUG/BoringSSL
2022-08-04T22:11:20.646444Z critical envoy backtrace #0: Envoy::SignalAction::sigHandler() [0x55787082aedc]
2022-08-04T22:11:20.646627Z critical envoy backtrace #1: __restore_rt [0x7fe4307ab140]
2022-08-04T22:11:20.729793Z critical envoy backtrace #2: Envoy::Tcp::ConnPoolImpl::deleteIsPending() [0x55786ee5e6e5]
2022-08-04T22:11:20.816228Z critical envoy backtrace #3: Envoy::Event::DispatcherImpl::deferredDelete() [0x557870440645]
2022-08-04T22:11:20.901629Z critical envoy backtrace #4: Envoy::Upstream::ClusterManagerImpl::ThreadLocalClusterManagerImpl::tcpConnPoolIsIdle() [0x55786edd54b1]
2022-08-04T22:11:20.994375Z critical envoy backtrace #5: Envoy::Upstream::ClusterManagerImpl::ThreadLocalClusterManagerImpl::ClusterEntry::tcpConnPoolImpl()::$_24::operator()() [0x55786ee05891]
2022-08-04T22:11:21.111388Z critical envoy backtrace #6: std::__1::__invoke<>() [0x55786ee0582d]
2022-08-04T22:11:21.222222Z critical envoy backtrace #7: std::__1::__invoke_void_return_wrapper<>::__call<>() [0x55786ee057dd]
[2022-08-04T22:11:20.230Z] "- - -" 0 - - - "-" 1419 3114 320 - "-" "-" "-" "-" "10.244.0.26:18443" inbound|18443|| 127.0.0.6:38235 10.244.0.26:18443 10.244.0.33:37728 outbound_.18443_._.headless.echo1-3-39127.svc.cluster.local -
[2022-08-04T22:11:20.230Z] "- - -" 0 - - - "-" 1419 3114 320 - "-" "-" "-" "-" "10.244.0.26:18443" inbound|18443|| 127.0.0.6:46235 10.244.0.26:18443 10.244.0.33:37732 outbound_.18443_._.headless.echo1-3-39127.svc.cluster.local -
[2022-08-04T22:11:20.230Z] "- - -" 0 - - - "-" 1419 3114 322 - "-" "-" "-" "-" "10.244.0.26:18443" inbound|18443|| 127.0.0.6:60737 10.244.0.26:18443 10.244.0.33:37730 outbound_.18443_._.headless.echo1-3-39127.svc.cluster.local -
[2022-08-04T22:11:20.552Z] "- - -" 0 - - - "-" 1419 3114 12 - "-" "-" "-" "-" "10.244.0.26:18443" inbound|18443|| 127.0.0.6:56849 10.244.0.26:18443 10.244.0.33:37774 outbound_.18443_._.headless.echo1-3-39127.svc.cluster.local -
2022-08-04T22:11:21.334186Z critical envoy backtrace #8: std::__1::__function::__alloc_func<>::operator()() [0x55786ee057ad]
2022-08-04T22:11:21.446329Z critical envoy backtrace #9: std::__1::__function::__func<>::operator()() [0x55786ee04969]
2022-08-04T22:11:21.588074Z critical envoy backtrace #10: std::__1::__function::__value_func<>::operator()() [0x557869d78252]
2022-08-04T22:11:21.707729Z critical envoy backtrace #11: std::__1::function<>::operator()() [0x557869d78215]
2022-08-04T22:11:21.837349Z critical envoy backtrace #12: Envoy::ConnectionPool::ConnPoolImplBase::checkForIdleAndNotify() [0x55786f362fcd]
2022-08-04T22:11:21.954837Z critical envoy backtrace #13: Envoy::ConnectionPool::ConnPoolImplBase::checkForIdleAndCloseIdleConnsIfDraining() [0x55786f362c73]
2022-08-04T22:11:22.071136Z critical envoy backtrace #14: Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient() [0x55786f321016]
2022-08-04T22:11:22.211542Z critical envoy backtrace #15: Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient() [0x55786f3210f9]
2022-08-04T22:11:22.365065Z critical envoy backtrace #16: std::__1::default_delete<>::operator()() [0x55786a10e6bc]
2022-08-04T22:11:22.489220Z critical envoy backtrace #17: std::__1::unique_ptr<>::reset() [0x55786a10e63c]
2022-08-04T22:11:22.610566Z critical envoy backtrace #18: Envoy::Event::DispatcherImpl::clearDeferredDeleteList() [0x55787043ca34]
2022-08-04T22:11:22.727033Z critical envoy backtrace #19: Envoy::Event::DispatcherImpl::DispatcherImpl()::$_2::operator()() [0x5578704487e9]
2022-08-04T22:11:22.841456Z critical envoy backtrace #20: std::__1::__invoke<>() [0x5578704487ad]
2022-08-04T22:11:22.949119Z critical envoy backtrace #21: std::__1::__invoke_void_return_wrapper<>::__call<>() [0x55787044875d]
2022-08-04T22:11:23.038542Z critical envoy backtrace #22: std::__1::__function::__alloc_func<>::operator()() [0x55787044872d]
2022-08-04T22:11:23.132226Z critical envoy backtrace #23: std::__1::__function::__func<>::operator()() [0x557870447879]
2022-08-04T22:11:23.132367Z critical envoy backtrace #24: std::__1::__function::__value_func<>::operator()() [0x557869d78252]
2022-08-04T22:11:23.132395Z critical envoy backtrace #25: std::__1::function<>::operator()() [0x557869d78215]
2022-08-04T22:11:23.224456Z critical envoy backtrace #26: Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl()::$_0::operator()() [0x557870798ab2]
2022-08-04T22:11:23.314165Z critical envoy backtrace #27: Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl()::$_0::__invoke() [0x557870798a79]
2022-08-04T22:11:23.407180Z critical envoy backtrace #28: event_process_active_single_queue [0x5578707ce10c]
2022-08-04T22:11:23.499323Z critical envoy backtrace #29: event_process_active [0x5578707c8988]
2022-08-04T22:11:23.607093Z critical envoy backtrace #30: event_base_loop [0x5578707c788c]
2022-08-04T22:11:23.710416Z critical envoy backtrace #31: Envoy::Event::LibeventScheduler::run() [0x55787079696f]
2022-08-04T22:11:23.806877Z critical envoy backtrace #32: Envoy::Event::DispatcherImpl::run() [0x557870441129]
2022-08-04T22:11:23.909969Z critical envoy backtrace #33: Envoy::Server::WorkerImpl::threadRoutine() [0x55786ecdca1e]
2022-08-04T22:11:23.998286Z critical envoy backtrace #34: Envoy::Server::WorkerImpl::start()::$_6::operator()() [0x55786ece6ce0]
2022-08-04T22:11:24.084979Z critical envoy backtrace #35: std::__1::__invoke<>() [0x55786ece6c9d]
2022-08-04T22:11:24.181252Z critical envoy backtrace #36: std::__1::__invoke_void_return_wrapper<>::__call<>() [0x55786ece6c4d]
2022-08-04T22:11:24.280837Z critical envoy backtrace #37: std::__1::__function::__alloc_func<>::operator()() [0x55786ece6c1d]
2022-08-04T22:11:24.370161Z critical envoy backtrace #38: std::__1::__function::__func<>::operator()() [0x55786ece5e19]
2022-08-04T22:11:24.370216Z critical envoy backtrace #39: std::__1::__function::__value_func<>::operator()() [0x557869d78252]
2022-08-04T22:11:24.370226Z critical envoy backtrace #40: std::__1::function<>::operator()() [0x557869d78215]
2022-08-04T22:11:24.458427Z critical envoy backtrace #41: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::{lambda()#1}::operator()() [0x557870c965cd]
2022-08-04T22:11:24.553854Z critical envoy backtrace #42: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::{lambda()#1}::__invoke() [0x557870c965a5]
2022-08-04T22:11:24.553982Z critical envoy backtrace #43: start_thread [0x7fe43079fea7]
I don't know when this started as we don't have regular runs with debug images (yet)
Repro steps: I don't have a minimal repro but we hit it in our CI easily
Example failiures: https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security-istiodremote_istio/1555312439514370048/artifacts/security-428b85071da243ee82d3fb/TestPassThroughFilterChain/DISABLE_with_PERMISSIVE/_test_context/echo1-2-83331-state2134015854/config-0/tproxy-v1-67ff8b6b87-8lkcl_istio-proxy.previous.log https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security-istiodremote_istio/1555312439514370048/artifacts/security-428b85071da243ee82d3fb/TestPassThroughFilterChain/DISABLE_with_PERMISSIVE/_test_context/echo1-2-83331-state2134015854/config-0/b-v1-b894cccd9-mkjzf_istio-proxy.previous.log https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-distroless_istio/1555312434737057792/artifacts/security-5a6e9dece7ce4accb167b8/TestReachability/global_mtls_strict/_test_context/echo1-3-39127-state3347915103/primary-0/headless-v1-6bccb45b85-mbb9w_istio-proxy.previous.log https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security_istio/1555312437832454144/artifacts/security-74627bac803844689bbd7f/TestPassThroughFilterChain/DISABLE/_test_context/echo1-3-55147-state4248486318/primary-0/b-v1-7ddb945cdb-9m4x5_istio-proxy.previous.log https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security_istio/1555312437832454144/artifacts/security-74627bac803844689bbd7f/TestPassThroughFilterChain/DISABLE/_test_context/echo1-3-55147-state4248486318/primary-0/tproxy-v1-59f9b9d764-rw5wl_istio-proxy.previous.log
Some core dumps: https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security_istio/1555312437832454144/artifacts/security-74627bac803844689bbd7f/TestPassThroughFilterChain/DISABLE/_test_context/echo1-3-55147-state4248486318/primary-0/b-v1-7ddb945cdb-9m4x5_core.proxy.25 https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security-istiodremote_istio/1555312439514370048/artifacts/security-428b85071da243ee82d3fb/TestPassThroughFilterChain/DISABLE_with_PERMISSIVE/headless/to_tproxy/mtls/tcp-wl-only%28allow%29/_test_context/echo1-2-83331-state2821089782/config-0/tproxy-v1-67ff8b6b87-8lkcl_core.proxy.26 https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security-istiodremote_istio/1555312439514370048/artifacts/security-428b85071da243ee82d3fb/TestPassThroughFilterChain/DISABLE_with_PERMISSIVE/headless/to_tproxy/mtls/tcp-wl-only%28allow%29/_test_context/echo1-2-83331-state2821089782/config-0/tproxy-v1-67ff8b6b87-8lkcl_core.proxy.28 https://storage.googleapis.com/istio-prow/pr-logs/pull/istio_istio/40290/integ-security-istiodremote_istio/1555312439514370048/artifacts/security-428b85071da243ee82d3fb/TestPassThroughFilterChain/DISABLE_with_PERMISSIVE/headless/to_tproxy/mtls/tcp-wl-only%28allow%29/_test_context/echo1-2-83331-state2821089782/config-0/tproxy-v1-67ff8b6b87-8lkcl_core.proxy.31
Envoy build: istio/proxy 01baf88a8942c273181c830b4307bfe70bd839c0, which is Envoyproxy a95d1b7f751e03c5033b84223c8b70acb786fd2b from 8/3
cc @kyessenov
The stack seems to say that a pool is deferred-deleted while not idle. That's not expected, could be related to lifecycle of CDS / EDS.
Anything I can do to get more info here?
cc @alyssawilk I cannot point to a reason except guessing it's related to lifecycle of internal sockets. Maybe someone else can have a better idea. The next step is to create a reproducer.
This one is not using internal listener at all, this is just mainline Istio from master
sorry back from vacation. Can you tell me a bit more about your set up? Most confusing is it looks like this is under void ConnPoolImplBase::checkForIdleAndNotify() { if (isIdleImpl()) { ... so we're verifying the pool is idle, we're calling the idle callbacks, wer're deleting the pool, and somewhere in between it's no longer idle? feel free to ping me internally if that's easier.
@alyssawilk I've seen that happen when Host lifecycle is broken (e.g. two Host structures created at the same memory address with ORIGINAL_DST). But there's not enough detail in the stack to tell exactly.
What info do you need? I can consistently reproduce running Istio tests in CI and locally, but haven't gotten to a minimal Envoy-only config.
Here are some debug logs
On the control plane side it looks like we push 2 CDS/EDS pairs back to back:
2022-08-24T14:34:00.701648Z info ads CDS: PUSH for node:tproxy-v1-7797758b46-zzsw4.echo2 resources:370 size:273.0kB cached:333/353
2022-08-24T14:34:00.710138Z info ads CDS: PUSH for node:tproxy-v1-7797758b46-r9254.echo1 resources:370 size:273.0kB cached:341/353
2022-08-24T14:34:00.732212Z info ads EDS: PUSH for node:tproxy-v1-7797758b46-zzsw4.echo2 resources:261 size:45.0kB empty:0 cached:238/261
2022-08-24T14:34:00.739877Z info ads EDS: PUSH for node:tproxy-v1-7797758b46-r9254.echo1 resources:261 size:45.0kB empty:0 cached:246/261
2022-08-24T14:34:00.759502Z info ads LDS: PUSH for node:tproxy-v1-7797758b46-zzsw4.echo2 resources:250 size:1.0MB
2022-08-24T14:34:00.776893Z info ads RDS: PUSH for node:tproxy-v1-7797758b46-zzsw4.echo2 resources:129 size:72.8kB cached:129/129
2022-08-24T14:34:00.777133Z info ads NDS: PUSH for node:tproxy-v1-7797758b46-zzsw4.echo2 resources:1 size:3.0kB
2022-08-24T14:34:00.782627Z info ads LDS: PUSH for node:tproxy-v1-7797758b46-r9254.echo1 resources:250 size:980.2kB
2022-08-24T14:34:00.802469Z info ads RDS: PUSH for node:tproxy-v1-7797758b46-r9254.echo1 resources:129 size:72.8kB cached:129/129
2022-08-24T14:34:01.013185Z info ads ADS: "10.244.0.48:51388" tproxy-v1-7797758b46-r9254.echo1-132 terminated
For me most useful was to track down the host lifecycle: which cluster it is, what Host in it (address and memory address). I think trace gives some of that, but full details require adding more printfs.
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.
This is still happening, not stale.
John, if you want traction from Envoy maintainers, we need a self-contained example. This is such a core part of Envoy that it's impossible to tell what leads to it.
We have it constantly reproducible on our test setup under live traffic. I've added backtrace before the assertion:
[critical][backtrace] [external/envoy/source/server/backtrace.h:91] Backtrace (use tools/stack_decode.py to get line numbers):
[critical][backtrace] [external/envoy/source/server/backtrace.h:92] Envoy version: 55f6103/1.24.0-dev/Clean/DEBUG/BoringSSL
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #0: Envoy::ConnectionPool::ConnPoolImplBase::deleteIsPendingImpl() [0x564bf554aec5]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #1: Envoy::Tcp::ConnPoolImpl::deleteIsPending() [0x564bf4523c65]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #2: Envoy::Tcp::ConnPoolImpl::deleteIsPending() [0x564bf4524d90]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #3: Envoy::Event::DispatcherImpl::deferredDelete() [0x564bf75c4363]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #4: Envoy::Upstream::ClusterManagerImpl::ThreadLocalClusterManagerImpl::tcpConnPoolIsIdle() [0x564bf442adc7]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #5: Envoy::Upstream::ClusterManagerImpl::ThreadLocalClusterManagerImpl::ClusterEntry::tcpConnPoolImpl()::$_24::operator()() [0x564bf4446ab9]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #6: std::__invoke_impl<>() [0x564bf4446996]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #7: std::__invoke_r<>() [0x564bf4446946]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #8: std::_Function_handler<>::_M_invoke() [0x564bf44466b0]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #9: std::function<>::operator()() [0x564bf25265d7]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #10: Envoy::ConnectionPool::ConnPoolImplBase::checkForIdleAndNotify() [0x564bf5560f40]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #11: Envoy::ConnectionPool::ConnPoolImplBase::checkForIdleAndCloseIdleConnsIfDraining() [0x564bf5560b30]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #12: Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient() [0x564bf54d4b3e]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #13: Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient() [0x564bf54d5190]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #14: Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient() [0x564bf54d51bd]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #15: std::default_delete<>::operator()() [0x564bf359cd34]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #16: std::__uniq_ptr_impl<>::reset() [0x564bf75da6ad]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #17: std::unique_ptr<>::reset() [0x564bf75d0b15]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #18: Envoy::Event::DispatcherImpl::clearDeferredDeleteList() [0x564bf75bdf7b]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #19: Envoy::Event::DispatcherImpl::DispatcherImpl()::$_2::operator()() [0x564bf75cc0be]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #20: std::__invoke_impl<>() [0x564bf75cc056]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #21: std::__invoke_r<>() [0x564bf75cc026]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #22: std::_Function_handler<>::_M_invoke() [0x564bf75cbe9b]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #23: std::function<>::operator()() [0x564bf25265d7]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #24: Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl()::$_0::operator()() [0x564bf7c955d9]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #25: Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl()::$_0::__invoke() [0x564bf7c955ac]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #26: event_process_active_single_queue [0x564bf82a3aa4]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #27: event_process_active [0x564bf8289ec2]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #28: event_base_loop [0x564bf8284125]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #29: Envoy::Event::LibeventScheduler::run() [0x564bf7c8ff7f]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #30: Envoy::Event::DispatcherImpl::run() [0x564bf75c5efb]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #31: Envoy::Server::WorkerImpl::threadRoutine() [0x564bf4276118]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #32: Envoy::Server::WorkerImpl::start()::$_6::operator()() [0x564bf4279f7e]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #33: std::__invoke_impl<>() [0x564bf4279f06]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #34: std::__invoke_r<>() [0x564bf4279eb6]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #35: std::_Function_handler<>::_M_invoke() [0x564bf4279c60]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #36: std::function<>::operator()() [0x564bf25265d7]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #37: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::{lambda()#1}::operator()() [0x564bf838d9e9]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #38: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::{lambda()#1}::__invoke() [0x564bf838d9bc]
[critical][backtrace] [external/envoy/source/server/backtrace.h:96] #39: start_thread [0x7fa9dddb8ea7]
[critical][assert] [external/envoy/source/common/conn_pool/conn_pool_base.cc:51] assert failure: isIdleImpl().
Any thoughts? cc @alyssawilk
I can add more debug prints to extract even more information - we have it happen couple times per day.
@belyalov This looks like regular TCP proxy? Is there something else going on (CONNECT, xDS updates, ORIGINAL_DST) on the data path?
Right, @kyessenov, it is a proxy with ORIGINAL_DST
, if simplified, it looks like:
// Listener definition simplified
DefaultFilterChain: &listener.FilterChain{
Name: "default",
Filters: []*listener.Filter{
// our extensions
networkMetadataFilter(),
networkContentFilteringFilter(),
networkRatelimitFilter(),
// standard tcp proxy
TCPProxyFilter(params.OriginalDstCluster, params.TCPAccessLog),
},
},
// TCP Proxy Filter
return &listener.Filter{
Name: "envoy.filters.network.tcp_proxy",
ConfigType: &listener.Filter_TypedConfig{
TypedConfig: utils.MustMarshalAny(&tcp_proxy.TcpProxy{
AccessLog: []*accesslogv3.AccessLog{
tcpAccessLog(logFilename, false),
},
StatPrefix: "tcp_proxy",
ClusterSpecifier: &tcp_proxy.TcpProxy_Cluster{
Cluster: clusterName,
},
MaxConnectAttempts: wrapperspb.UInt32(2),
}),
},
}
// Cluster definition
cluster := &cluster.Cluster{
Name: name,
ClusterDiscoveryType: &cluster.Cluster_Type{
Type: cluster.Cluster_ORIGINAL_DST,
},
CircuitBreakers: &cluster.CircuitBreakers{
Thresholds: []*cluster.CircuitBreakers_Thresholds{
{
Priority: core.RoutingPriority_DEFAULT,
MaxConnections: &wrapperspb.UInt32Value{
Value: 16384 * 100,
},
TrackRemaining: true,
},
{
Priority: core.RoutingPriority_HIGH,
MaxConnections: &wrapperspb.UInt32Value{
Value: 16384 * 100,
},
TrackRemaining: true,
},
},
},
LbPolicy: cluster.Cluster_CLUSTER_PROVIDED,
DnsLookupFamily: cluster.Cluster_V4_ONLY,
}
yeah the stack trace is confusing me. essentially it's if (isIdleImpl) { doDeletionCode(); } and doDeletionCode fails isIdleImpl checks. clearly there's some code between the original check and the final check that makes the statement no longer true but I'm having trouble finding it via code inspection. If I got you a patch with some increased logging since you have a repro case would you be able to apply and get me logs?
@alyssawilk I remember seeing this assertion violation when manually stress testing prior to https://github.com/envoyproxy/envoy/pull/22371. It went away after that PR for HTTP usage, but I see that this is still happening on 1.24. My guess was there is some pointer address collision when synthesizing hosts rapidly. Having detailed info about when hosts get created in ORIGINAL_DST would be helpful.
If I got you a patch with some increased logging since you have a repro case would you be able to apply and get me logs?
yeah, absolutely, please go for it, happy to help, @alyssawilk
Ok no patch yet (sorry, mostly focused on EnvoyCon) but I've at least got an integration test of basic original dst cluster additions and removals both for TCP and HTTP neither of which I don't think we had previously. @kyessenov if you have ideas of how I could better tweak the tests I sent your way to repro the thrashing issues you were seeing lmk, otherwise I'll try to add some sensible logging based on those tests and ship them over to @belyalov tomorrow
The trashing issue was solved for HTTP in the merged PR (hosts are now reused more often). What made me suspect it was seeing identical memory addresses for hosts in original_dst implementation, there I just printed the host address here. I think it's already there actually.
oh awesome, thanks for adding the logging. did you need creation and deletion log points, or was just creation sufficient?
I think the deletion event is printed by cluster already, as part of its host lifecycle management.
in that case @howardjohn could you share full logs somewhere @kyessenov and I have access to?
Here are 3 different instances. Let me know if you need something else
Seems like it's in tcp pool (filtered to connection):
2022-11-01T21:51:19.286022Z trace envoy main external/envoy/source/common/event/dispatcher_impl.cc:250 item added to deferred deletion list (size=3) thread=45
2022-11-01T21:51:19.286040Z trace envoy filter external/envoy/source/common/network/listener_filter_buffer_impl.cc:95 onFileEvent: 1 thread=45
2022-11-01T21:51:19.286062Z trace envoy filter external/envoy/source/common/network/listener_filter_buffer_impl.cc:60 recv returned: 517 thread=45
2022-11-01T21:51:19.286081Z trace envoy filter external/envoy/source/extensions/filters/listener/http_inspector/http_inspector.cc:92 http inspector: http_parser parsed 0 chars, error code: 16 thread=45
2022-11-01T21:51:19.286090Z trace envoy filter external/envoy/source/extensions/filters/listener/http_inspector/http_inspector.cc:122 http inspector: done: false thread=45
2022-11-01T21:51:19.286191Z debug envoy filter external/envoy/source/common/tcp_proxy/tcp_proxy.cc:199 [C720] new tcp proxy session thread=45
2022-11-01T21:51:19.286229Z trace envoy connection external/envoy/source/common/network/connection_impl.cc:357 [C720] readDisable: disable=true disable_count=0 state=0 buffer_length=0 thread=45
2022-11-01T21:51:19.286279Z debug envoy filter external/envoy/source/common/tcp_proxy/tcp_proxy.cc:371 [C720] Creating connection to cluster InboundPassthroughClusterIpv4 thread=45
2022-11-01T21:51:19.286333Z trace envoy upstream external/envoy/source/common/upstream/original_dst_cluster.cc:53 Using existing host InboundPassthroughClusterIpv410.244.0.34:18083 10.244.0.34:18083. thread=45
2022-11-01T21:51:19.286387Z debug envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:290 trying to create new connection thread=45
2022-11-01T21:51:19.286420Z trace envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:291 ConnPoolImplBase 0x55dc54b12280, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1 thread=45
2022-11-01T21:51:19.286443Z debug envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:145 creating a new connection (connecting=0) thread=45
2022-11-01T21:51:19.286545Z debug envoy connection external/envoy/source/common/network/connection_impl.cc:924 [C722] connecting to 10.244.0.34:18083 thread=45
2022-11-01T21:51:19.286624Z debug envoy connection external/envoy/source/common/network/connection_impl.cc:943 [C722] connection in progress thread=45
2022-11-01T21:51:19.286640Z trace envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:131 not creating a new connection, shouldCreateNewConnection returned false. thread=45
2022-11-01T21:51:19.286661Z debug envoy conn_handler external/envoy/source/server/active_tcp_listener.cc:147 [C720] new connection from 10.244.0.27:57714 thread=45
2022-11-01T21:51:19.286675Z trace envoy main external/envoy/source/common/event/dispatcher_impl.cc:250 item added to deferred deletion list (size=4) thread=45
2022-11-01T21:51:19.286696Z trace envoy main external/envoy/source/common/event/dispatcher_impl.cc:125 clearing deferred deletion list (size=4) thread=45
2022-11-01T21:51:19.286711Z debug envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:214 [C717] destroying stream: 0 remaining thread=45
2022-11-01T21:51:19.286728Z debug envoy pool external/envoy/source/common/conn_pool/conn_pool_base.cc:453 invoking idle callbacks - is_draining_for_deletion_=false thread=45
2022-11-01T21:51:19.286748Z trace envoy upstream external/envoy/source/common/upstream/cluster_manager_impl.cc:1796 Idle pool, erasing pool for host InboundPassthroughClusterIpv410.244.0.34:18083 thread=45
2022-11-01T21:51:19.286758Z critical envoy assert external/envoy/source/common/conn_pool/conn_pool_base.cc:38 assert failure: isIdleImpl(). thread=45
Looking at this one thing that I notice is each upstream connection seems to trigger a new inbound connection. @howardjohn can you talk me through your data flow here? My integration tests used original_dst with a port override so the traffic didn't go through the Envoy twice so I wonder if that's why my test case didn't repro and there's some reentrant style bug.
I am not quite sure I follow. Wouldn't that mean there is a loop?
The request flow should just be app -> outbound sidecar -> inbound sidecar -> other app
. The test is basically sending a bunch of different requests between client+server pairs. Looking more closely though, there is 1 pair that can be both the client+server - log1.txt
. Note I am not sure the crash happens when calling itself, just that at some point it does. log2 and log3 shouldn't be calling themselves, though.
sorry by loop I meant does the request traverse Envoy twice? It looked to me like in log1 that creating an upstream connection on your envoy resulted in creating a downstream connection for the same envoy (unless I'm misreading?)
Yes, in log1.txt
the app can be calling itself. So we have app -> outbound envoy -> inbound envoy (the same envoy instance!) -> app (the same app!)
.
For the other logs, this shouldn't be happening.
I closed https://github.com/envoyproxy/envoy/issues/24573 to consolidate here, but FYI there is another similar assertion failure, likely the same root cause per kuat
Up this thread:
I've added some debug prints and seems like it is failing on this assert:
https://github.com/envoyproxy/envoy/blob/1d8868797e4b2720e8681cba84191b33b730e3f8/source/common/conn_pool/conn_pool_base.cc#L39
[2023-07-21 17:26:37.490][16][critical][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:44] !!! deleteIsPendingImpl() assertion: false 1 false
[2023-07-21 17:26:37.490][16][critical][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:46] state: ConnPoolImplBase 0x5c0ee38aa00, ready_clients_.size(): 0, busy_clients_.size()
: 0, connecting_clients_.size(): 1, connecting_stream_capacity_: 1, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1
[2023-07-21 17:26:37.490][16][critical][backtrace] [external/envoy/source/server/backtrace.h:104] Caught ASSERT_CONN_POOL, suspect faulting address 0x0
[2023-07-21 17:26:37.490][16][critical][backtrace] [external/envoy/source/server/backtrace.h:91] Backtrace (use tools/stack_decode.py to get line numbers):
[2023-07-21 17:26:37.490][16][critical][backtrace] [external/envoy/source/server/backtrace.h:92] Envoy version: 7583b80/1.26.3/Clean/DEBUG/BoringSSL
[2023-07-21 17:26:37.529][16][critical][backtrace] [external/envoy/source/server/backtrace.h:96] #0: Envoy::ConnectionPool::ConnPoolImplBase::deleteIsPendingImpl() [0x563605997519]
[2023-07-21 17:26:37.565][16][critical][backtrace] [external/envoy/source/server/backtrace.h:96] #1: Envoy::Tcp::ConnPoolImpl::deleteIsPending() [0x563605371216]
[2023-07-21 17:26:37.605][16][critical][backtrace] [external/envoy/source/server/backtrace.h:96] #2: Envoy::Event::DispatcherImpl::deferredDelete() [0x563606443621]
[2023-07-21 17:26:37.648][16][critical][backtrace] [external/envoy/source/server/backtrace.h:96] #3: Envoy::Upstream::ClusterManagerImpl::ThreadLocalClusterManagerImpl::tcpConnPoolIsIdle() [0x56360535eb47]
I'm not sure what it means, gonna spend a bit more time on understanding this.
Any help appreciated :)