From 8bdfe08a0bfa1bc53b3d5dfa7a63b48ec3101026 Mon Sep 17 00:00:00 2001 From: Aysha Afrah Ziya Date: Wed, 14 Oct 2026 21:04:11 +0530 Subject: [PATCH] fix data race in SqliteLogger::callback --- src/loggers/bt_sqlite_logger.cpp | 44 ++++++++++++++------------ tests/gtest_loggers.cpp | 54 ++++++++++++++++++++++++++++++++ 2 files changed, 78 insertions(+), 20 deletions(-) diff --git a/src/loggers/bt_sqlite_logger.cpp b/src/loggers/bt_sqlite_logger.cpp index f5960dbfa..f2ed29b4f 100644 --- a/src/loggers/bt_sqlite_logger.cpp +++ b/src/loggers/bt_sqlite_logger.cpp @@ -168,28 +168,8 @@ void SqliteLogger::callback(Duration timestamp, const TreeNode& node, { using namespace std::chrono; const int64_t tm_usec = int64_t(duration_cast(timestamp).count()); - monotonic_timestamp_ = std::max(monotonic_timestamp_ + 1, tm_usec); - - long elapsed_time = 0; - - if(prev_status == NodeStatus::IDLE && status == NodeStatus::RUNNING) - { - starting_time_[&node] = monotonic_timestamp_; - } - - if(prev_status == NodeStatus::RUNNING && status != NodeStatus::RUNNING) - { - elapsed_time = monotonic_timestamp_; - auto it = starting_time_.find(&node); - if(it != starting_time_.end()) - { - elapsed_time -= it->second; - } - } Transition trans; - trans.timestamp = monotonic_timestamp_; - trans.duration = elapsed_time; trans.node_uid = node.UID(); trans.status = status; @@ -199,7 +179,31 @@ void SqliteLogger::callback(Duration timestamp, const TreeNode& node, } { + // This callback may be invoked concurrently from multiple threads + // (e.g. two ThreadedAction completing at the same time), so + // monotonic_timestamp_ and starting_time_ must be guarded too. const std::scoped_lock lk(queue_mutex_); + monotonic_timestamp_ = std::max(monotonic_timestamp_ + 1, tm_usec); + + long elapsed_time = 0; + + if(prev_status == NodeStatus::IDLE && status == NodeStatus::RUNNING) + { + starting_time_[&node] = monotonic_timestamp_; + } + + if(prev_status == NodeStatus::RUNNING && status != NodeStatus::RUNNING) + { + elapsed_time = monotonic_timestamp_; + auto it = starting_time_.find(&node); + if(it != starting_time_.end()) + { + elapsed_time -= it->second; + } + } + + trans.timestamp = monotonic_timestamp_; + trans.duration = elapsed_time; transitions_queue_.push_back(trans); } queue_cv_.notify_one(); diff --git a/tests/gtest_loggers.cpp b/tests/gtest_loggers.cpp index 20b078ace..b355be2d3 100644 --- a/tests/gtest_loggers.cpp +++ b/tests/gtest_loggers.cpp @@ -22,6 +22,7 @@ #include #include #include +#include #include @@ -527,6 +528,59 @@ TEST_F(LoggerTest, SqliteLogger_MultipleTicks) ASSERT_TRUE(std::filesystem::exists(filepath)); } +// A ThreadedAction completes on its own worker thread, so the logger callback +// of each instance runs concurrently with the ones invoked by the main thread. +namespace +{ +class ConcurrentAction : public BT::ThreadedAction +{ +public: + ConcurrentAction(const std::string& name, const BT::NodeConfig& config) + : BT::ThreadedAction(name, config) + {} + + static BT::PortsList providedPorts() + { + return {}; + } + + BT::NodeStatus tick() override + { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + return BT::NodeStatus::SUCCESS; + } +}; +} // namespace + +TEST_F(LoggerTest, SqliteLogger_ConcurrentTransitions) +{ + factory.registerNodeType("ConcurrentAction"); + + const std::string xml_text = R"( + + + + + + + + )"; + + auto tree = factory.createTreeFromText(xml_text); + std::string filepath = test_dir + "/concurrent.db3"; + + { + SqliteLogger logger(tree, filepath); + for(int i = 0; i < 50; i++) + { + tree.tickWhileRunning(); + tree.haltTree(); + } + } + + ASSERT_TRUE(std::filesystem::exists(filepath)); +} + // ============ Multiple loggers simultaneously ============ TEST_F(LoggerTest, MultipleLoggers)