"pure virtual method called" in grpc:grpc_client_integration_test

[ivitjuk]

Title: grpc:grpc_client_integration_test fails randomly with pure virtual method call error

Description:
I am trying to build Envoy on amazonlinux:2.0.20181010 with gcc (GCC) 7.3.1 20180303 and are running into some flaky tests with Envoy 1.8.0. Specifically grpc:grpc_client_integration_test is failing randomly because of "pure virtual method called" exception. I pasted the test log to: https://gist.github.com/ivitjuk/40d63bffd9a6cf12b738c628a1e48dc5
Test failed only once, out of 1000 runs: https://gist.github.com/ivitjuk/954167c4117cea26929a38d7b73c170b
To me it seems like call to monotonicTime() time here https://github.com/envoyproxy/envoy/blob/master/include/envoy/stats/timespan.h#L32 is somehow getting resolved to the pure virtual method of the base class, while it really should have been resolved to this in the tests: https://github.com/envoyproxy/envoy/blob/master/test/test_common/test_time.h#L25

[jmarantz]

could we coax a stack-trace out of the system on a pure virtual call?

In the distant past I was able to figure out how to override the pure_virtual handler to something that produced a stack trace, but that was on a vastly different toolchain in a vastly different era.

[ivitjuk]

Yeah, it's void __cxa_pure_virtual(void); as described in http://libcxxabi.llvm.org/spec.html

I'll give it a try.

[ivitjuk]

I patched grpc_client_integration_test.cc with the diff bellow, results are attached. Not sure if the patch did the right thing as the log doesn't contain much of an additional info.

diff --git a/test/common/grpc/BUILD b/test/common/grpc/BUILD
index f6377a1a..417057f1 100644
--- a/test/common/grpc/BUILD
+++ b/test/common/grpc/BUILD
@@ -87,6 +87,7 @@ envoy_cc_test_library(
     hdrs = ["grpc_client_integration.h"],
     deps = [
         "//source/common/common:assert_lib",
+       "//source/server:backtrace_lib",
         "//test/mocks/secret:secret_mocks",
         "//test/test_common:utility_lib",
     ],
diff --git a/test/common/grpc/grpc_client_integration_test.cc b/test/common/grpc/grpc_client_integration_test.cc  
index 30d92a2a..2d0a47e1 100644
--- a/test/common/grpc/grpc_client_integration_test.cc
+++ b/test/common/grpc/grpc_client_integration_test.cc
@@ -7,6 +7,21 @@

 #include "test/common/grpc/grpc_client_integration_test_harness.h"

+#include "server/backtrace.h"
+
+extern "C" {
+       static int __cxa_pure_virtual() __attribute__((noinline, used));
+       static int __cxa_pure_virtual()
+       {
+               Envoy::BackwardsTrace tracer;
+               tracer.capture();
+               tracer.logTrace();
+               assert(0);
+               return 0;
+       }
+}
+
+
 namespace Envoy {
 namespace Grpc {
 namespace {

test.log

[alyssawilk]

Got another similar failure:

[ RUN ] IpVersionsClientType/GrpcClientIntegrationTest.MissingGrpcStatus/0
pure virtual method called
terminate called without an active exception
[2018-11-26 20:24:56.347][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:125] Caught Aborted, suspect faulting address 0xad370000000f
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:94] Backtrace thr<149> obj</lib/x86_64-linux-gnu/libc.so.6> (If unsymbolized, use tools/stack_decode.py):
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #0 0x7f9488d56fcf (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #1 0x7f9488d583f9 (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:104] thr<149> obj</usr/lib/x86_64-linux-gnu/libstdc++.so.6>
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #2 0x7f94893675a8 (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #3 0x7f948936d7f9 (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #4 0x7f948936d854 (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #5 0x7f948936e5f2 (unknown)
[2018-11-26 20:24:56.348][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:104] thr<149> obj</usr/local/google/home/alyssar/.cache/bazel/_bazel_alyssar/3a7172795bcbacd0230af40aaea95285/sandbox/linux-sandbox/485/execroot/envoy/bazel-out/k8-dbg/bin/test/common/grpc/grpc_client_integration_test.runfiles/envoy/test/common/grpc/grpc_client_integration_test>
[2018-11-26 20:24:56.367][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #6 0x56439dd0b3cb Envoy::Stats::Timespan::getRawDuration()
[2018-11-26 20:24:56.386][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #7 0x56439dd0b376 Envoy::Stats::Timespan::complete()
[2018-11-26 20:24:56.405][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #8 0x56439dd0a8c6 Envoy::Server::ConnectionHandlerImpl::ActiveConnection::~ActiveConnection()
[2018-11-26 20:24:56.425][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #9 0x56439dd0a927 Envoy::Server::ConnectionHandlerImpl::ActiveConnection::~ActiveConnection()
[2018-11-26 20:24:56.445][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #10 0x56439dd0db3b std::default_delete<>::operator()()
[2018-11-26 20:24:56.465][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #11 0x56439e66f3c8 std::unique_ptr<>::reset()
[2018-11-26 20:24:56.484][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #12 0x56439e66d783 Envoy::Event::DispatcherImpl::clearDeferredDeleteList()
[2018-11-26 20:24:56.503][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #13 0x56439e66d146 Envoy::Event::DispatcherImpl::DispatcherImpl()::{lambda()#1}::operator()()
[2018-11-26 20:24:56.523][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #14 0x56439e66eb1e std::_Function_handler<>::_M_invoke()
[2018-11-26 20:24:56.543][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #15 0x56439dc1198d std::function<>::operator()()
[2018-11-26 20:24:56.562][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #16 0x56439e673d7c Envoy::Event::TimerImpl::TimerImpl()::{lambda()#1}::operator()()
[2018-11-26 20:24:56.581][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #17 0x56439e673dab Envoy::Event::TimerImpl::TimerImpl()::{lambda()#1}::_FUN()
[2018-11-26 20:24:56.709][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #18 0x56439ed66a9b event_process_active_single_queue.isra.29
[2018-11-26 20:24:56.728][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #19 0x56439ed6704e event_process_active
[2018-11-26 20:24:56.748][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #20 0x56439ed6abcf event_base_loop
[2018-11-26 20:24:56.767][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #21 0x56439e66e84d Envoy::Event::DispatcherImpl::run()
[2018-11-26 20:24:56.786][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #22 0x56439dc1c72c Envoy::FakeUpstream::threadRoutine()
[2018-11-26 20:24:56.805][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #23 0x56439dc1bf58 Envoy::FakeUpstream::FakeUpstream()::{lambda()#1}::operator()()
[2018-11-26 20:24:56.824][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #24 0x56439dc1f0fa std::_Function_handler<>::_M_invoke()
[2018-11-26 20:24:56.824][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #25 0x56439dc1198d std::function<>::operator()()
[2018-11-26 20:24:56.843][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #26 0x56439ed4e5f5 Envoy::Thread::ThreadImpl::ThreadImpl()::{lambda()#1}::operator()()
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #27 0x56439ed4e619 Envoy::Thread::ThreadImpl::ThreadImpl()::{lambda()#1}::_FUN()
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:104] thr<149> obj</lib/x86_64-linux-gnu/libpthread.so.0>
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<149> #28 0x7f948996b493 start_thread
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:104] thr<149> obj</lib/x86_64-linux-gnu/libc.so.6>
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<149> #29 0x7f9488e0ca8e (unknown)
[2018-11-26 20:24:56.862][000149][critical][backtrace] [bazel-out/k8-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:121] end backtrace thread 149