[YCQL] Uncaught exception when handling wrong CQL timestamp format

[mbautin]

Jira Link: DB-2787

Description

ts2|pid295891|:11262 libc++abi: terminating with uncaught exception of type boost::wrapexcept<boost::gregorian::bad_month>: Month number is out of range 1..12
ts2|pid295891|:11262 *** Aborted at 1656024028 (unix time) try "date -d @1656024028" if you are using GNU date ***
ts2|pid295891|:11262 PC: @                0x0 (unknown)
ts2|pid295891|:11262 *** SIGABRT (@0x71000483d3) received by PID 295891 (TID 0x7f2b6d429700) from PID 295891; stack trace: ***
ts2|pid295891|:11262     @     0x7f2b7a0970a7 __GI_raise
ts2|pid295891|:11262     @     0x7f2b7a0984aa __GI_abort
ts2|pid295891|:11262     @          0x4233681 abort_message
ts2|pid295891|:11262     @          0x42332ea demangling_terminate_handler()
ts2|pid295891|:11262     @          0x4232e95  std::__terminate()
ts2|pid295891|:11262     @          0x4235ff1  __cxxabiv1::call_terminate()
ts2|pid295891|:11262     @          0x4235db8  __cxxabiv1::scan_eh_tab()
ts2|pid295891|:11262     @          0x4235198 __gxx_personality_v0
ts2|pid295891|:11262     @          0x2a4be33 unwind_phase2
ts2|pid295891|:11262     @          0x2a4c2f6 _Unwind_Resume
ts2|pid295891|:11262     @          0x2ced406  boost::CV::simple_exception_policy<>::on_error()
ts2|pid295891|:11262     @          0x3880b32  yb::DateTime::TimestampFromString()
ts2|pid295891|:11262     @          0x3b03b7a  yb::ql::Executor::PTConstToPB()
ts2|pid295891|:11262     @          0x3aff8d7  yb::ql::Executor::ColumnArgsToPB()
ts2|pid295891|:11262     @          0x3b1def0  yb::ql::Executor::ExecTreeNode()
ts2|pid295891|:11262     @          0x3b32b7a  yb::ql::Executor::Execute()
ts2|pid295891|:11262     @          0x3b32931  yb::ql::Executor::ExecuteAsync()
ts2|pid295891|:11262     @          0x3aec075  yb::ql::QLProcessor::ExecuteAsync()
ts2|pid295891|:11262     @          0x3aeb9f3  yb::ql::QLProcessor::RunAsync()
ts2|pid295891|:11262     @          0x3ab8985  yb::cqlserver::CQLProcessor::ProcessRequest()
ts2|pid295891|:11262     @          0x3ac2e9c  yb::cqlserver::CQLProcessor::ProcessCall()
ts2|pid295891|:11262     @          0x3ae4db6  yb::cqlserver::CQLServiceImpl::Handle()
ts2|pid295891|:11262     @          0x34c069e  yb::rpc::ServicePoolImpl::Handle()
ts2|pid295891|:11262     @          0x34120e4  yb::rpc::InboundCall::InboundCallTask::Run()
ts2|pid295891|:11262     @          0x34cf5bc  yb::rpc::(anonymous namespace)::Worker::Execute()
ts2|pid295891|:11262     @          0x3a96443  yb::Thread::SuperviseThread()
ts2|pid295891|:11262     @     0x7f2b79c4b694 start_thread
ts2|pid295891|:11262     @     0x7f2b7a14a41d __clone

[mbautin]

This is an LTO specific issue. Also it seems to be specific to Boost exceptions. If I throw an std::exception from my test directly, it gets caught fine.

Getting this stack trace with lldb:

* thread #1, name = 'tostring-test-l', stop reason = signal SIGABRT
  * frame #0: 0x00007f2d53e380a7 libc.so.6`__GI_raise(sig=6) at raise.c:54
    frame #1: 0x00007f2d53e394aa libc.so.6`__GI_abort at abort.c:89
    frame #2: 0x00000000024aa341 tostring-test-lto`::abort_message(format=<unavailable>) at abort_message.cpp:78:5
    frame #3: 0x00000000024a9faa tostring-test-lto`demangling_terminate_handler() at cxa_default_handlers.cpp:66:21
    frame #4: 0x00000000024a9b56 tostring-test-lto`std::__terminate(func=<unavailable>)()) at cxa_handlers.cpp:59:9
    frame #5: 0x00000000024ac36d tostring-test-lto`__cxxabiv1::scan_eh_tab(results=0x00007ffe4e58ec60, actions=<unavailable>, native_exception=false, unwind_exception=<unavailable>, context=<unavailable>)::scan_results&, _Unwind_Action, bool, _Unwind_Exception*, _Unwind_Context*) at cxa_personality.cpp:0:40
    frame #6: 0x00000000024abc10 tostring-test-lto`::__gxx_personality_v0(version=<unavailable>, actions=_UA_CLEANUP_PHASE, exceptionClass=<unavailable>, unwind_exception=0x00000000053fe420, context=0x00007ffe4e58f218) at cxa_personality.cpp:947:5
    frame #7: 0x0000000002047d03 tostring-test-lto`unwind_phase2(uc=<unavailable>, cursor=0x00007ffe4e58f218, exception_object=0x00000000053fe420) at UnwindLevel1.c:197:11
    frame #8: 0x0000000002048846 tostring-test-lto`_Unwind_Resume(exception_object=0x00000000053fe420) at UnwindLevel1.c:394:5
    frame #9: 0x00000000022b0b67 tostring-test-lto`boost::CV::simple_exception_policy<unsigned short, (unsigned short)1, (unsigned short)12, boost::gregorian::bad_month>::on_error((null)=<unavailable>, (null)=<unavailable>, (null)=<unavailable>) at constrained_value.hpp:0
    frame #10: 0x00000000022b63e2 tostring-test-lto`yb::DateTime::TimestampFromString(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, yb::DateTime::InputFormat const&) [inlined] boost::CV::constrained_value<boost::CV::simple_exception_policy<unsigned short, (unsigned short)1, (unsigned short)12, boost::gregorian::bad_month> >::assign(this=<unavailable>, value=1) at constrained_value.hpp:77:9
    frame #11: 0x00000000022b63cb tostring-test-lto`yb::DateTime::TimestampFromString(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, yb::DateTime::InputFormat const&) [inlined] boost::CV::constrained_value<boost::CV::simple_exception_policy<unsigned short, (unsigned short)1, (unsigned short)12, boost::gregorian::bad_month> >::constrained_value(this=<unavailable>, value=1) at constrained_value.hpp:48:7
    frame #12: 0x00000000022b63cb tostring-test-lto`yb::DateTime::TimestampFromString(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, yb::DateTime::InputFormat const&) [inlined] boost::gregorian::greg_month::greg_month(this=<unavailable>, theMonth=1) at greg_month.hpp:59:61
    frame #13: 0x00000000022b63cb tostring-test-lto`yb::DateTime::TimestampFromString(str=<unavailable>, input_format=<unavailable>) at date_time.cc:187:28
    frame #14: 0x0000000002017948 tostring-test-lto`yb::util_test::TestDateTimeCase_TimeStampDataType_Test::TestBody(this=<unavailable>) at tostring-test.cc:290:26
    frame #15: 0x0000000002063662 tostring-test-lto`void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [inlined] void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(object=0x00000000054001b0, method=<unavailable>, location="")(), char const*) at gtest.cc:2402:10
    frame #16: 0x0000000002063653 tostring-test-lto`void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(object=<unavailable>, method=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00, location="")(), char const*) at gtest.cc:2438:14
    frame #17: 0x000000000206c1c2 tostring-test-lto`testing::internal::UnitTestImpl::RunAllTests() [inlined] testing::Test::Run(this=0x00000000054001b0) at gtest.cc:2474:5
    frame #18: 0x000000000206bf5d tostring-test-lto`testing::internal::UnitTestImpl::RunAllTests() [inlined] testing::TestInfo::Run(this=0x0000000004996b40) at gtest.cc:2656:11
    frame #19: 0x000000000206bdcc tostring-test-lto`testing::internal::UnitTestImpl::RunAllTests() at gtest.cc:2774:28
    frame #20: 0x000000000206bc2f tostring-test-lto`testing::internal::UnitTestImpl::RunAllTests(this=<unavailable>) at gtest.cc:4649:43
    frame #21: 0x00000000021743e5 tostring-test-lto`main [inlined] bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(object=0x0000000004998000, method=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00, location=<unavailable>)(), char const*) at gtest.cc:2402:10
    frame #22: 0x00000000021743dd tostring-test-lto`main at gtest.cc:2438:14
    frame #23: 0x00000000021743bf tostring-test-lto`main [inlined] testing::UnitTest::Run(this=<unavailable>) at gtest.cc:4257:10
    frame #24: 0x0000000002174341 tostring-test-lto`main [inlined] RUN_ALL_TESTS() at gtest.h:2233:46
    frame #25: 0x0000000002174333 tostring-test-lto`main(argc=1, argv=0x00007ffe4e58fc58) at test_main.cc:105:13
    frame #26: 0x00007f2d53e25825 libc.so.6`__libc_start_main(main=(tostring-test-lto`main at test_main.cc:88), argc=2, argv=0x00007ffe4e58fc58, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007ffe4e58fc48) at libc-start.c:289
    frame #27: 0x0000000001fa3029 tostring-test-lto`_start + 41

Built yugabyte-db-thirdparty with this patch, off of the commit yugabyte/yugabyte-db-thirdparty@52b25a9:

diff --git a/python/yugabyte_db_thirdparty/builder.py b/python/yugabyte_db_thirdparty/builder.py
index fc3521c..db68c77 100644
--- a/python/yugabyte_db_thirdparty/builder.py
+++ b/python/yugabyte_db_thirdparty/builder.py
@@ -499,6 +499,8 @@ class Builder(BuilderInterface):
         if self.build_type == BUILD_TYPE_TSAN:
             self.compiler_flags += TSAN_FLAGS

+        self.compiler_flags.append('-g')
+
     def add_linuxbrew_flags(self) -> None:
         if using_linuxbrew():
             lib_dir = os.path.join(get_linuxbrew_dir(), 'lib')

Then built yugabyte-db off of commit f27f2a3 like so:

export YB_THIRDPARTY_DIR=$HOME/code/yugabyte-db-thirdparty
export YB_LINUXBREW_DIR=/opt/yb-build/brew/linuxbrew-20181203T161736v9
./yb_build.sh --clang13 --lto full release --linuxbrew --save-log

Created a script build-support/test_lto.sh:

#!/usr/bin/env bash

. "${BASH_SOURCE%/*}/common-build-env.sh"

activate_virtualenv
set_pythonpath

if [[ $( uname -m ) == "x86_64" ]]; then
  build_root_basename=release-clang13-linuxbrew-full-lto-ninja
else
  build_root_basename=release-clang12-full-lto-ninja
fi

set -x
"$YB_SRC_ROOT/python/yb/dependency_graph.py" \
    --build-root "$YB_SRC_ROOT/build/${build_root_basename}" \
    --file-regex "^.*/tostring-test$" \
    link-whole-program \
    "$@"

Modified a test:

diff --git a/src/yb/util/tostring-test.cc b/src/yb/util/tostring-test.cc
index b65449c..5b573cc 100644
--- a/src/yb/util/tostring-test.cc
+++ b/src/yb/util/tostring-test.cc
@@ -28,6 +28,8 @@
 #include "yb/util/monotime.h"
 #include "yb/util/tostring.h"
 #include "yb/util/uuid.h"
+#include "yb/util/date_time.h"
+#include "yb/util/result.h"

 namespace yb {
 // We should use namespace other than yb::ToString to check how does ToString works
@@ -257,5 +259,37 @@ TEST(ToStringTest, Struct) {
   ASSERT_EQ(TestClass(42, "test").ToString(), "{ a: 42 b: test }");
 }

+namespace {
+
+void ThrowEx1Func() {
+  throw std::invalid_argument("Testing exception 1");
+}
+
+void ThrowEx2Func() {
+  throw std::invalid_argument("Testing exception 2");
+}
+
+}
+
+TEST(TestDateTimeCase, ThrowException) {
+  void (*f1)() = &ThrowEx1Func;
+  void (*f2)() = &ThrowEx2Func;
+
+  try {
+    LOG(INFO) << "Calling function that will throw an exception";
+    if (rand() % 2 == 0) f1(); else f2();
+  } catch (std::invalid_argument& e) {
+    LOG(INFO) << "Caught exception: " << e.what();
+  }
+}
+
+TEST(TestDateTimeCase, TimeStampDataType) {
+  string ts_str = "2018-13-14 13:24:56.987+01:00";
+  // DateTime date_time;
+  //Timestamp ts;
+  Result<Timestamp> ts = DateTime::TimestampFromString(ts_str);
+  LOG(INFO) << "validated timestamp is: " << ts;
+}
+
 } // namespace util_test
 } // namespace yb

The test case that throws an exception in the same test works fine:

#  build/release-clang13-linuxbrew-full-lto-ninja/tests-util/tostring-test-lto --gtest_filter=TestDateTimeCase.ThrowException
Note: Google Test filter = TestDateTimeCase.ThrowException
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from TestDateTimeCase
[ RUN      ] TestDateTimeCase.ThrowException
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0726 00:40:14.116119 10049 tostring-test.cc:279] Calling function that will throw an exception
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=1 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=6 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
I0726 00:40:14.116276 10049 tostring-test.cc:282] Caught exception: Testing exception 2
[       OK ] TestDateTimeCase.ThrowException (0 ms)
[----------] 1 test from TestDateTimeCase (0 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (0 ms total)
[  PASSED  ] 1 test.
00:40:14 07/26/2022 centos@

(there is some additional logging added to cxa_persionality.cc, part of libc++abi).

However, the test that attempts to catch an exception thrown from Boost, crashes:

#  build/release-clang13-linuxbrew-full-lto-ninja/tests-util/tostring-test-lto --gtest_filter=TestDateTimeCase.TimeStampDataType
Note: Google Test filter = TestDateTimeCase.TimeStampDataType
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from TestDateTimeCase
[ RUN      ] TestDateTimeCase.TimeStampDataType
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=1 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=1 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=2 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=2 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
libc++abi: terminating with uncaught exception of type boost::wrapexcept<boost::gregorian::bad_month>: Month number is out of range 1..12
*** Aborted at 1658796057 (unix time) try "date -d @1658796057" if you are using GNU date ***
PC: @                0x0 (unknown)
*** SIGABRT (@0x3eb00002752) received by PID 10066 (TID 0x7f2f6f75be80) from PID 10066; stack trace: ***
    @     0x7f2f6eab60a7 __GI_raise
    @     0x7f2f6eab74aa __GI_abort
    @          0x24aa341 abort_message
    @          0x24a9faa demangling_terminate_handler()
    @          0x24a9b56 std::__terminate()
    @          0x24ac38d __cxxabiv1::scan_eh_tab()
    @          0x24abc4c __gxx_personality_v0
    @          0x2047d03 unwind_phase2
    @          0x2048846 _Unwind_Resume
    @          0x22b0b67 boost::CV::simple_exception_policy<>::on_error()
    @          0x22b63e2 yb::DateTime::TimestampFromString()
    @          0x2017948 yb::util_test::TestDateTimeCase_TimeStampDataType_Test::TestBody()
    @          0x2063662 testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x206c1c2 testing::internal::UnitTestImpl::RunAllTests()
    @          0x21743e5 main
    @     0x7f2f6eaa3825 __libc_start_main
    @          0x1fa3029 (unknown)
Aborted (core dumped)

[mbautin]

Potentially relevant issues:

• C++ exceptions are aborting the process, even if caught android/ndk#289
• https://stackoverflow.com/questions/51673343/clang-with-libc-exceptions (thanks @sureshdash2022-yb for finding this one).

[mbautin]

A test that calls std::stoi with an invalid argument also leads to a failure to catch the exception:

TEST(ToStringTest, StringToIntException) {
  std::string s = "abc";
  int i = 0;
  try {
    i = std::stoi(s);
  } catch (std::invalid_argument& e) {
    LOG(INFO) << "Caught exception in string to int conversion: " << e.what();
  }
  LOG(INFO) << "i=" << i;
}

Crashes with this stack trace:

# build/release-clang13-linuxbrew-full-lto-ninja/tests-util/tostring-test-lto --gtest_filter=ToStringTest.StringToIntException
Note: Google Test filter = ToStringTest.StringToIntException
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from ToStringTest
[ RUN      ] ToStringTest.StringToIntException
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=1 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=1 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=2 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
native_exception=1 exceptionClass=4849336966747728640 kOurExceptionClass=4849336966747728640 get_vendor_and_language=18446744073709551360actions=2 _UA_CLEANUP_PHASE=2 _UA_HANDLER_FRAME=4
libc++abi: terminating with uncaught exception of type std::invalid_argument: stoi: no conversion
*** Aborted at 1658800694 (unix time) try "date -d @1658800694" if you are using GNU date ***
PC: @                0x0 (unknown)
*** SIGABRT (@0x3eb00007257) received by PID 29271 (TID 0x7fb4e1a0be80) from PID 29271; stack trace: ***
    @     0x7fb4e0d660a7 __GI_raise
    @     0x7fb4e0d674aa __GI_abort
    @          0x24aa5d1 abort_message
    @          0x24aa23a demangling_terminate_handler()
    @          0x24a9de6 std::__terminate()
    @          0x24ac61d __cxxabiv1::scan_eh_tab()
    @          0x24abedc __gxx_personality_v0
    @          0x2047f93 unwind_phase2
    @          0x2048ad6 _Unwind_Resume
    @          0x2466c02 std::__1::stoi()
    @          0x20179cf yb::util_test::ToStringTest_StringToIntException_Test::TestBody()
    @          0x20638f2 testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x206c452 testing::internal::UnitTestImpl::RunAllTests()
    @          0x2174675 main
    @     0x7fb4e0d53825 __libc_start_main
    @          0x1fa3029 (unknown)
Aborted (core dumped)

The debug logging lines were produced by the following code added to cxa_personality.cpp in libc++abi:

    scan_results results;
    // Process a catch handler for a native exception first.

    // Added this:
    fprintf(stderr,
            "native_exception=%d "
            "exceptionClass=%lu "
            "kOurExceptionClass=%lu "
            "get_vendor_and_language=%lu"
            "actions=%lu "
            "_UA_CLEANUP_PHASE=%lu "
            "_UA_HANDLER_FRAME=%lu"
            "\n",
            native_exception,
            exceptionClass,
            kOurExceptionClass,
            get_vendor_and_language,
            actions,
            _UA_CLEANUP_PHASE,
            _UA_HANDLER_FRAME);

    if (actions == (_UA_CLEANUP_PHASE | _UA_HANDLER_FRAME) &&
        native_exception) {

[mbautin]

Useful links for exception handling:

• https://www.airs.com/blog/archives/464
• https://llvm.org/docs/ExceptionHandling.html
• https://www.ucw.cz/~hubicka/papers/abi/node25.html
• https://martin.uy/blog/understanding-the-gcc_except_table-section-in-elf-binaries-gcc/

[mbautin]

Also a useful document on exception handling: https://itanium-cxx-abi.github.io/cxx-abi/exceptions.pdf

[mbautin]

Here are some details on the workaround:

• Added debugging logging to UnwindLevel1.c ( base version from https://github.com/yugabyte/llvm-project/releases/tag/llvmorg-13.0.1-yb-1 ) https://gist.githubusercontent.com/mbautin/a49f3b10213395bc2d7da2d21561f61e/raw
• Added debug logging to cxa_personality.cpp ( https://gist.githubusercontent.com/mbautin/6e56b5fde9836be66cabfb17ade76fd0/raw , same base version )
• Found that if we just exit normally from scan_eh_table in case it does not contain an entry for the given address during the cleanup phase, exception handling starts working in the LTO binary.

    if (native_exception && actions == _UA_CLEANUP_PHASE) {
      // This might happen for LTO binaries. Assume there is no handler and no cleanup.
      results.reason = _URC_CONTINUE_UNWIND;
      return;
    }

It remains to be verified that all the destructors are being called correctly.

[mbautin]

It does appear that the destructor gets called, added to tostring-test.cc. Built and linked as already shown in earlier comments above.

Test (with the exception being thrown inside libc++ -- this bug does not affect exceptions being thrown from the same compilation unit for some reason):

class MyClass {
 public:
  MyClass() { std::cout << "MyClass constructor called" << std::endl; }
  ~MyClass() { std::cout << "MyClass destructor called" << std::endl; }
};

TEST(ToStringTest, StringToIntException) {
  std::string s = "abc";
  int i = 0;
  try {
    MyClass a;
    i = std::stoi(s);
  } catch (std::invalid_argument& e) {
    LOG(INFO) << "Caught exception in string to int conversion: " << e.what();
  }
  LOG(INFO) << "i=" << i;
}

Output: https://gist.githubusercontent.com/mbautin/a177b3ac12817f9ac72b541ffc2d93af/raw (notice the "MyClass destructor called" line).

[mbautin]

Reopening until the updated third-party dependencies are pulled into master.

[es1024]

Third-party dependencies pulled into master with f2702bb

[mbautin]

New issue: #22191