From 86776a57e9ebfe4408d68e36f57069a11d1f85f6 Mon Sep 17 00:00:00 2001 From: simobenziane Date: Thu, 10 Sep 2026 09:54:28 +0200 Subject: [PATCH] fix FileLogger2: drain the transition queue in the destructor after joining the writer thread FileLogger2::writerLoop() checks `loop` between batches, and ~FileLogger2() sets `loop = false` and joins without draining transitions_queue. A transition pushed after the writer's last swap -- typically the root's RUNNING->IDLE from a haltTree() issued right before the logger is destroyed -- is lost, so the .btlog ends mid-flight. Reproduced with a serve loop that halts the tree on a broken pipe and then resets its logger; under load the last IDLE is missing in a fraction of runs. This extracts the batch write into writeBatch(), adds drainQueue() (swap under the mutex, then write), and calls it in the destructor after the join, before the file is closed. No behaviour change for callers. A new looping test, FileLogger2_DrainsQueueAfterHaltThenImmediateDestroy, ticks a tree to RUNNING, halts it, and destroys the logger immediately, then reads the .btlog back and asserts the root's last transition is IDLE, 300 times per run to exercise the scheduling gap. On the unpatched destructor it fails intermittently under load (3/10 and 10/10 process invocations failed across two load runs); with the fix, 3000/3000 iterations passed under the same load. Co-Authored-By: Claude Sonnet 5 --- .../loggers/bt_file_logger_v2.h | 6 ++ src/loggers/bt_file_logger_v2.cpp | 47 ++++++--- tests/gtest_loggers.cpp | 99 +++++++++++++++++++ 3 files changed, 137 insertions(+), 15 deletions(-) diff --git a/include/behaviortree_cpp/loggers/bt_file_logger_v2.h b/include/behaviortree_cpp/loggers/bt_file_logger_v2.h index db0f4cd74..692bb78bb 100644 --- a/include/behaviortree_cpp/loggers/bt_file_logger_v2.h +++ b/include/behaviortree_cpp/loggers/bt_file_logger_v2.h @@ -1,6 +1,7 @@ #pragma once #include "behaviortree_cpp/loggers/abstract_logger.h" +#include #include #include @@ -61,6 +62,11 @@ class FileLogger2 : public StatusChangeLogger std::unique_ptr _p; void writerLoop(); + // Write one batch of transitions to the file (the loop's own 9-byte layout, one place). + void writeBatch(std::deque& transitions); + // Move whatever is queued onto this thread and write it: the destructor's drain after the + // writer thread has joined. + void drainQueue(); }; } // namespace BT diff --git a/src/loggers/bt_file_logger_v2.cpp b/src/loggers/bt_file_logger_v2.cpp index 845d37da9..00ba2c923 100644 --- a/src/loggers/bt_file_logger_v2.cpp +++ b/src/loggers/bt_file_logger_v2.cpp @@ -100,6 +100,10 @@ FileLogger2::~FileLogger2() _p->loop = false; _p->queue_cv.notify_one(); _p->writer_thread.join(); + // The writer thread checks `loop` between batches; a transition pushed after its last swap + // (a haltTree() right before this destructor is the common case) would otherwise never reach + // the file. Drain it here, on the destroying thread, after the join. + drainQueue(); _p->file_stream.close(); } @@ -146,22 +150,35 @@ void FileLogger2::writerLoop() // simple way to pop all the transitions from _p->transitions_queue into transitions std::swap(transitions, _p->transitions_queue); } - { - const std::scoped_lock file_lock(_p->file_mutex); - while(!transitions.empty()) - { - const auto trans = transitions.front(); - std::array write_buffer{}; - std::memcpy(write_buffer.data(), &trans.timestamp_usec, 6); - std::memcpy(write_buffer.data() + 6, &trans.node_uid, 2); - std::memcpy(write_buffer.data() + 8, &trans.status, 1); - - _p->file_stream.write(write_buffer.data(), 9); - transitions.pop_front(); - } - _p->file_stream.flush(); - } + writeBatch(transitions); + } +} + +void FileLogger2::writeBatch(std::deque& transitions) +{ + const std::scoped_lock file_lock(_p->file_mutex); + while(!transitions.empty()) + { + const auto trans = transitions.front(); + std::array write_buffer{}; + std::memcpy(write_buffer.data(), &trans.timestamp_usec, 6); + std::memcpy(write_buffer.data() + 6, &trans.node_uid, 2); + std::memcpy(write_buffer.data() + 8, &trans.status, 1); + + _p->file_stream.write(write_buffer.data(), 9); + transitions.pop_front(); + } + _p->file_stream.flush(); +} + +void FileLogger2::drainQueue() +{ + std::deque transitions; + { + std::unique_lock lock(_p->queue_mutex); + std::swap(transitions, _p->transitions_queue); } + writeBatch(transitions); } } // namespace BT diff --git a/tests/gtest_loggers.cpp b/tests/gtest_loggers.cpp index 1daae3f3b..2f95af54e 100644 --- a/tests/gtest_loggers.cpp +++ b/tests/gtest_loggers.cpp @@ -16,7 +16,10 @@ #include "behaviortree_cpp/loggers/bt_minitrace_logger.h" #include "behaviortree_cpp/loggers/bt_sqlite_logger.h" +#include +#include #include +#include #include #include @@ -192,6 +195,102 @@ TEST_F(LoggerTest, FileLogger2_MultipleTicks) ASSERT_TRUE(std::filesystem::exists(filepath)); } +// A minimal action that stays RUNNING until halted -- SimpleActionNode/SyncActionNode explicitly +// forbid returning RUNNING, so the drain-race repro below needs a real (if synchronous) action +// node instead. +namespace +{ +class AlwaysRunningNode : public BT::ActionNodeBase +{ +public: + AlwaysRunningNode(const std::string& name, const BT::NodeConfig& config) + : BT::ActionNodeBase(name, config) + {} + + static BT::PortsList providedPorts() + { + return {}; + } + + BT::NodeStatus tick() override + { + return BT::NodeStatus::RUNNING; + } + + void halt() override + {} +}; +} // namespace + +// FileLogger2's destructor used to join the writer thread without draining +// _p->transitions_queue afterward: a transition pushed after the writer's last swap (typically +// the root's RUNNING->IDLE from a haltTree() issued right before the logger is destroyed) could +// be lost, leaving the .btlog missing its final transition. The window is a scheduling race, not +// deterministic, so this loops many iterations rather than asserting on a single run. +TEST_F(LoggerTest, FileLogger2_DrainsQueueAfterHaltThenImmediateDestroy) +{ + BT::BehaviorTreeFactory local_factory; + local_factory.registerNodeType("AlwaysRunning"); + + const std::string xml_text = R"( + + + + + + + )"; + + constexpr int kIterations = 300; + + for(int i = 0; i < kIterations; i++) + { + auto tree = local_factory.createTreeFromText(xml_text); + const std::string filepath = test_dir + "/drain_" + std::to_string(i) + ".btlog"; + const uint16_t root_uid = tree.rootNode()->UID(); + + { + FileLogger2 logger(tree, filepath); + tree.tickOnce(); // root -> RUNNING, pushed onto the queue + tree.haltTree(); // root -> IDLE, pushed right before the logger is destroyed + } // ~FileLogger2() runs here: join the writer thread, then (with the fix) drain the queue + + // Parse the .btlog by hand (format documented in bt_file_logger_v2.h): 18-byte magic + // ("BTCPP4-FileLogger2"), 1-byte protocol, 4-byte XML length, the XML itself, 8-byte first + // timestamp, then a sequence of 9-byte Transition records (6 bytes timestamp, 2 bytes + // node_uid, 1 byte status). + std::ifstream file(filepath, std::ios::binary); + ASSERT_TRUE(file.is_open()) << "iteration " << i; + + file.seekg(18 + 1); + int32_t xml_len = 0; + file.read(reinterpret_cast(&xml_len), sizeof(xml_len)); + ASSERT_TRUE(file.good()) << "iteration " << i; + file.seekg(xml_len, std::ios::cur); + file.seekg(8, std::ios::cur); // skip the first timestamp + + uint8_t last_root_status = 0xFF; + std::array record{}; + while(file.read(record.data(), record.size())) + { + uint16_t uid = 0; + uint8_t status = 0xFF; + std::memcpy(&uid, record.data() + 6, sizeof(uid)); + std::memcpy(&status, record.data() + 8, sizeof(status)); + if(uid == root_uid) + { + last_root_status = status; + } + } + + ASSERT_EQ(last_root_status, static_cast(NodeStatus::IDLE)) + << "iteration " << i << ": the root's last recorded transition is status " + << int(last_root_status) + << ", not IDLE(0) -- the tree's halt never reached the .btlog before the file " + "closed"; + } +} + // ============ MinitraceLogger tests ============ TEST_F(LoggerTest, MinitraceLogger_Creation)