chore: passert failure should flush logs (#5682)

Resolves CORE-325.

One of the concerns reported in
[CORE-290](https://linear.app/tiledb/issue/CORE-290/consolidation-stdbad-alloc)
was that the process aborting did not flush logs and consequently did
not leave a lot of clues about what happened.

We cannot always intercept events which lead to process shutdown, but
one place we have managed to do so is assertion failures in core-owned
code. #5514 added `iassert` and `passert` routines, which throws an
exception or halts the process in the event of a failure respectively;
#5532 added support to run arbitrary callbacks in the event of a
`passert` failure.

This pull request leverages that capability to flush all logs in the
event of a `passert` failure so that if a customer sees a `passert`
failure we will know that the logs are up to date.

---
TYPE: NO_HISTORY
DESC: Flush logs if there is a `passert` failure

Author: rroelke

scripts/linter.py

@@ -17,6 +17,8 @@
 heap_memory_ignored_files = frozenset(
     [
         "allocate_unique.h",
+        'assert.cc',
+        'assert.h',
         "dynamic_memory.h",
         "unit_dynamic_memory.cc",
         "heap_profiler.h",

test/ci/CMakeLists.txt

@@ -9,7 +9,7 @@ target_include_directories(test_assert
     Catch2::Catch2
 )
 
-target_link_libraries(test_assert PUBLIC tiledb_Catch2WithMain)
+target_link_libraries(test_assert PUBLIC tiledb_Catch2WithMain assert)
 
 target_compile_definitions(
   test_assert
@@ -23,7 +23,7 @@ add_executable(
   try_assert.cc
 )
 
-target_link_libraries(try_assert PUBLIC assert)
+target_link_libraries(try_assert PUBLIC assert baseline)
 
 target_include_directories(try_assert
   PRIVATE

test/ci/test_assert.cc

@@ -36,9 +36,19 @@
 
 #include <algorithm>
 #include <cassert>
+#include <filesystem>
+#include <fstream>
 #include <iostream>
 #include <list>
 
+#include "tiledb/common/assert.h"
+
+#ifdef TILEDB_ASSERTIONS
+static constexpr bool builtWithAssertions = true;
+#else
+static constexpr bool builtWithAssertions = false;
+#endif
+
 #ifdef _WIN32
 std::vector<int> assert_exit_codes{3};
 #else
@@ -50,24 +60,56 @@ std::vector<int> assert_exit_codes{
 #endif
 
 TEST_CASE("CI: Test assertions configuration", "[ci][assertions]") {
-  int retval = system(TILEDB_PATH_TO_TRY_ASSERT);
+  char command[2048];
+  std::optional<std::filesystem::path> try_assert_logfile;
+  if (builtWithAssertions) {
+    try_assert_logfile =
+        std::filesystem::temp_directory_path() / "try_assert.log";
+    sprintf(
+        command,
+        "%s %s",
+        TILEDB_PATH_TO_TRY_ASSERT,
+        try_assert_logfile.value().string().c_str());
+  } else {
+    sprintf(command, "%s", TILEDB_PATH_TO_TRY_ASSERT);
+  }
+
+  const int retval = system(command);
 
   // in case value is one not currently accepted, report what was returned.
   std::cout << "retval is " << retval << " (0x" << std::hex << retval
             << ") from " << TILEDB_PATH_TO_TRY_ASSERT << std::endl;
 
-#ifdef TILEDB_ASSERTIONS
-  REQUIRE(
-      std::find(assert_exit_codes.begin(), assert_exit_codes.end(), retval) !=
-      assert_exit_codes.end());
-#else
-  (void)assert_exit_codes;
-  REQUIRE(retval == 0);
-#endif
+  if (builtWithAssertions) {
+    REQUIRE(
+        std::find(assert_exit_codes.begin(), assert_exit_codes.end(), retval) !=
+        assert_exit_codes.end());
+
+    // the log should have flushed due to passert callback
+    std::vector<std::string> logcontents;
+    {
+      std::ifstream logstream(try_assert_logfile.value());
+      REQUIRE(logstream.is_open());
+
+      std::string logline;
+      while (std::getline(logstream, logline)) {
+        logcontents.push_back(logline);
+      }
+    }
+    std::filesystem::remove(try_assert_logfile.value());
+
+    REQUIRE(logcontents.size() == 1);
+    if (!logcontents.empty()) {
+      REQUIRE(logcontents[0].find("begin passert(false)") != std::string::npos);
+    }
+  } else {
+    (void)assert_exit_codes;
+    REQUIRE(retval == 0);
+  }
 }
 
 TEST_CASE("CI: Test libc assertions configuration", "[ci][assertions]") {
-  int retval = system(TILEDB_PATH_TO_TRY_LIBC_ASSERT);
+  const int retval = system(TILEDB_PATH_TO_TRY_LIBC_ASSERT);
 
   // report return value
   std::cout << "retval is " << retval << " (0x" << std::hex << retval
@@ -102,3 +144,50 @@ TEST_CASE("CI: Test libc assertions configuration", "[ci][assertions]") {
     REQUIRE(retval == 0);
   }
 }
+
+TEST_CASE("CI: passert callback registration non-FIFO", "[assertions]") {
+  int x = 0;
+  int y = 100;
+  int z = 10000;
+  std::vector<int> order_;
+
+  using R = tiledb::common::PAssertFailureCallbackRegistration;
+
+  std::unique_ptr<R> inc_x(new R([&]() { order_.push_back(x++); }));
+  std::unique_ptr<R> inc_y(new R([&]() { order_.push_back(y++); }));
+  std::unique_ptr<R> inc_z(new R([&]() { order_.push_back(z++); }));
+
+  REQUIRE(order_.empty());
+
+  tiledb::common::passert_failure_run_callbacks();
+  CHECK(order_ == std::vector<int>{10000, 100, 0});
+  order_.clear();
+
+  tiledb::common::passert_failure_run_callbacks();
+  CHECK(order_ == std::vector<int>{10001, 101, 1});
+  order_.clear();
+
+  SECTION("Remove x") {
+    inc_x.reset();
+
+    tiledb::common::passert_failure_run_callbacks();
+    CHECK(order_ == std::vector<int>{10002, 102});
+    order_.clear();
+  }
+
+  SECTION("Remove y") {
+    inc_y.reset();
+
+    tiledb::common::passert_failure_run_callbacks();
+    CHECK(order_ == std::vector<int>{10002, 2});
+    order_.clear();
+  }
+
+  SECTION("Remove z") {
+    inc_z.reset();
+
+    tiledb::common::passert_failure_run_callbacks();
+    CHECK(order_ == std::vector<int>{102, 2});
+    order_.clear();
+  }
+}

test/ci/try_assert.cc

@@ -1,13 +1,28 @@
 #include <cassert>
+#include <filesystem>
 #include <iostream>
 
+#include <spdlog/sinks/basic_file_sink.h>
+#include <spdlog/spdlog.h>
+
 #include "tiledb/common/assert.h"
+#include "tiledb/common/logger.h"
 
 #if defined(_MSC_VER)
 #include <crtdbg.h>
 #endif
 
-int main(int, char**) {
+int main(int argc, char** argv) {
+  std::optional<tiledb::common::Logger> log;
+  if (argc > 1) {
+    const auto logname =
+        std::filesystem::path(std::string(argv[0])).filename().string();
+    const auto logfile = std::filesystem::path(std::string(argv[1]));
+
+    auto spdlogger = spdlog::basic_logger_mt(logname, logfile.string());
+    log.emplace(spdlogger);
+  }
+
 #if defined(_MSC_VER)
   // We disable the following events on abort:
   // _WRITE_ABORT_MSG: Display message box with Abort, Retry, Ignore
@@ -19,8 +34,16 @@ int main(int, char**) {
   _CrtSetReportMode(_CRT_ASSERT, _CRTDBG_MODE_FILE);
   _CrtSetReportFile(_CRT_ASSERT, _CRTDBG_FILE_STDERR);
 #endif
+  if (log.has_value()) {
+    log.value().error("begin passert(false)");
+  }
+
   passert(false);
 
+  if (log.has_value()) {
+    log.value().error("end passert(false)");
+  }
+
   std::cout << "Assert did not exit!" << std::endl;
   return 0;
 }

tiledb/common/assert.cc

@@ -45,17 +45,45 @@ AssertFailure::AssertFailure(const std::string& what)
   throw AssertFailure(file, line, expr);
 }
 
-static std::mutex passertFailureCallbackMutex;
-static std::vector<std::function<void()>> passertFailureCallbacks;
+struct PAssertFailureCallbackProcessState {
+  using self_type = PAssertFailureCallbackProcessState;
 
-[[noreturn]] void passert_failure_abort(void) {
-  {
-    for (auto& callback : passertFailureCallbacks) {
-      std::unique_lock<std::mutex> lk(passertFailureCallbackMutex);
-      callback();
+  static std::shared_ptr<self_type> get() {
+    static std::shared_ptr<self_type> singleton;
+    if (singleton == nullptr) {
+      singleton.reset(new self_type());
     }
+    return singleton;
+  }
+
+  std::mutex mutex_;
+  std::list<std::function<void()>> callbacks_;
+
+ private:
+  PAssertFailureCallbackProcessState() {
+  }
+};
+
+void passert_failure_run_callbacks(void) {
+  auto state = PAssertFailureCallbackProcessState::get();
+  if (!state) {
+    // NB: we expect this to be unreachable.
+    // `!state` should only happen if the singleton has been
+    // destructed, which should only occur when the shared library
+    // is unloaded or when the process exits. In either case we
+    // should not see a `passert` failure at that point - or there
+    // are worse problems.
+    return;
   }
 
+  std::unique_lock<std::mutex> lk(state->mutex_);
+  for (auto& callback : state->callbacks_) {
+    callback();
+  }
+}
+
+[[noreturn]] void passert_failure_abort(void) {
+  passert_failure_run_callbacks();
   std::abort();
 }
 
@@ -71,15 +99,19 @@ static std::vector<std::function<void()>> passertFailureCallbacks;
 #ifdef TILEDB_ASSERTIONS
 
 PAssertFailureCallbackRegistration::PAssertFailureCallbackRegistration(
-    std::function<void()>&& callback) {
-  std::unique_lock<std::mutex> lk(passertFailureCallbackMutex);
-  passertFailureCallbacks.push_back(
+    std::function<void()>&& callback)
+    : process_state_(PAssertFailureCallbackProcessState::get()) {
+  std::unique_lock<std::mutex> lk(process_state_->mutex_);
+
+  process_state_->callbacks_.push_front(
       std::forward<std::function<void()>>(callback));
+
+  callback_node_ = process_state_->callbacks_.begin();
 }
 
 PAssertFailureCallbackRegistration::~PAssertFailureCallbackRegistration() {
-  std::unique_lock<std::mutex> lk(passertFailureCallbackMutex);
-  passertFailureCallbacks.pop_back();
+  std::unique_lock<std::mutex> lk(process_state_->mutex_);
+  process_state_->callbacks_.erase(callback_node_);
 }
 
 #endif

tiledb/common/assert.h

@@ -90,6 +90,10 @@
 #include <cstdlib>
 #include <functional>
 #include <iostream>
+#include <list>
+#include <memory>
+
+#include "tiledb/common/macros.h"
 
 #define __SOURCE__ (&__FILE__[__SOURCE_DIR_PATH_SIZE__])
 
@@ -169,6 +173,18 @@ template <typename... Args>
   throw AssertFailure(file, line, expr, fmt, std::forward<Args>(fmt_args)...);
 }
 
+/**
+ * Structure holding the process-level state required to run `passert`
+ * failure callbacks.
+ */
+struct PAssertFailureCallbackProcessState;
+
+/**
+ * Runs registered callbacks prior to aborting the process in the event of a
+ * `passert` failure. See `PAssertFailureCallbackRegistration`.
+ */
+void passert_failure_run_callbacks(void);
+
 /**
  * Aborts the process upon `passert` failure.
  */
@@ -217,16 +233,34 @@ template <typename... Args>
  * Registers a callback to run upon `passert` failure.
  * This can be used to print any diagnostic info prior to aborting the process.
  */
-struct PAssertFailureCallbackRegistration {
 #ifdef TILEDB_ASSERTIONS
+
+struct PAssertFailureCallbackRegistration {
   PAssertFailureCallbackRegistration(std::function<void()>&& callback);
   ~PAssertFailureCallbackRegistration();
+  DISABLE_COPY_AND_COPY_ASSIGN(PAssertFailureCallbackRegistration);
+
+ private:
+  /**
+   * Lazy initialization of global process state.
+   * This avoids the "static initialization order fiasco".
+   */
+  std::shared_ptr<PAssertFailureCallbackProcessState> process_state_;
+
+  /** Reference to the registered callback for deregistering */
+  std::list<std::function<void()>>::const_iterator callback_node_;
+};
+
 #else
+
+struct PAssertFailureCallbackRegistration {
   PAssertFailureCallbackRegistration(std::function<void()>&&) {
   }
-#endif
+  DISABLE_COPY_AND_COPY_ASSIGN(PAssertFailureCallbackRegistration);
 };
 
+#endif
+
 }  // namespace tiledb::common
 
 #ifdef TILEDB_ASSERTIONS

tiledb/common/logger.cc

@@ -73,7 +73,8 @@ Logger::Logger(
     const Logger::Format format,
     const bool root)
     : name_(name)
-    , root_(root) {
+    , root_(root)
+    , passert_callback_flush_([this]() { flush(); }) {
   logger_ = spdlog::get(name_);
   if (logger_ == nullptr) {
 #ifdef _WIN32
@@ -92,7 +93,8 @@ Logger::Logger(
   set_format(format);
 }
 
-Logger::Logger(shared_ptr<spdlog::logger> logger) {
+Logger::Logger(shared_ptr<spdlog::logger> logger)
+    : passert_callback_flush_([this]() { flush(); }) {
   logger_ = std::move(logger);
 }
 
@@ -312,6 +314,12 @@ std::string Logger::add_tag(const std::string& tag, uint64_t id) {
   return tags;
 }
 
+void Logger::flush() const {
+  if (logger_) {
+    logger_->flush();
+  }
+}
+
 /* ********************************* */
 /*              GLOBAL               */
 /* ********************************* */