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)