Fix a data race in collection notifier logging and extract some duplicated code

tgoyne · tgoyne · commit 0e94a90f18aa · 2024-03-12T16:44:42.000-07:00
m_run_time_point was read on the target thread while being written on the
worker thread without any locking involved.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -7,6 +7,7 @@
 ### Fixed
 * Fixed conflict resolution bug which may result in an crash when the AddInteger instruction on Mixed properties is merged against updates to a non-integer type ([PR #7353](https://github.com/realm/realm-core/pull/7353)).
 * Fix a spurious crash related to opening a Realm on background thread while the process was in the middle of exiting ([#7420](https://github.com/realm/realm-core/issues/7420jj))
+* Fix a data race in change notification delivery when running at debug log level ([PR #7402](https://github.com/realm/realm-core/pull/7402), since v14.0.0).
 
 ### Breaking changes
 * Remove `realm_scheduler_set_default_factory()` and `realm_scheduler_has_default_factory()`, and change the `Scheduler` factory function to a bare function pointer rather than a `UniqueFunction` so that it does not have a non-trivial destructor.
diff --git a/src/realm/object-store/impl/collection_notifier.cpp b/src/realm/object-store/impl/collection_notifier.cpp
@@ -307,8 +307,9 @@ void CollectionNotifier::prepare_handover()
     REALM_ASSERT(m_change.empty());
     m_has_run = true;
 
-#ifdef REALM_DEBUG
     util::CheckedLockGuard lock(m_callback_mutex);
+    m_run_time_point = std::chrono::steady_clock::now();
+#ifdef REALM_DEBUG
     for (auto& callback : m_callbacks)
         REALM_ASSERT(!callback.skip_next);
 #endif
@@ -330,10 +331,59 @@ void CollectionNotifier::before_advance()
     });
 }
 
+static void log_changeset(util::Logger* logger, const CollectionChangeSet& changes, std::string_view description,
+                          std::chrono::microseconds elapsed)
+{
+    if (!logger) {
+        return;
+    }
+
+    logger->log(util::LogCategory::notification, util::Logger::Level::debug,
+                "Delivering notifications for %1 after %2 us", description, elapsed.count());
+    if (!logger->would_log(util::Logger::Level::trace)) {
+        return;
+    }
+    if (changes.empty()) {
+        logger->log(util::LogCategory::notification, util::Logger::Level::trace, "   No changes");
+    }
+    else {
+        if (changes.collection_root_was_deleted) {
+            logger->log(util::LogCategory::notification, util::Logger::Level::trace, "   collection deleted");
+        }
+        else if (changes.collection_was_cleared) {
+            logger->log(util::LogCategory::notification, util::Logger::Level::trace, "   collection cleared");
+        }
+        else {
+            auto log = [logger](const char* change, const IndexSet& index_set) {
+                if (auto cnt = index_set.count()) {
+                    std::ostringstream ostr;
+                    bool first = true;
+                    for (auto [a, b] : index_set) {
+                        if (!first)
+                            ostr << ',';
+                        if (b > a + 1) {
+                            ostr << '[' << a << ',' << b - 1 << ']';
+                        }
+                        else {
+                            ostr << a;
+                        }
+                        first = false;
+                    }
+                    logger->log(util::LogCategory::notification, util::Logger::Level::trace, "   %1 %2: %3", cnt,
+                                change, ostr.str().c_str());
+                }
+            };
+            log("deletions", changes.deletions);
+            log("insertions", changes.insertions);
+            log("modifications", changes.modifications);
+        }
+    }
+}
+
 void CollectionNotifier::after_advance()
 {
     using namespace std::chrono;
-    auto t1 = steady_clock::now();
+    auto now = steady_clock::now();
 
     for_each_callback([&](auto& lock, auto& callback) {
         if (callback.initial_delivered && callback.changes_to_deliver.empty()) {
@@ -346,51 +396,9 @@ void CollectionNotifier::after_advance()
         // acquire a local reference to the callback so that removing the
         // callback from within it can't result in a dangling pointer
         auto cb = callback.fn;
+        auto elapsed = duration_cast<microseconds>(now - m_run_time_point);
         lock.unlock_unchecked();
-        if (m_logger) {
-            m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
-                          "Delivering notifications for %1 after %2 us", m_description,
-                          duration_cast<microseconds>(t1 - m_run_time_point).count());
-            if (m_logger->would_log(util::Logger::Level::trace)) {
-                if (changes.empty()) {
-                    m_logger->log(util::LogCategory::notification, util::Logger::Level::trace, "   No changes");
-                }
-                else {
-                    if (changes.collection_root_was_deleted) {
-                        m_logger->log(util::LogCategory::notification, util::Logger::Level::trace,
-                                      "   collection deleted");
-                    }
-                    else if (changes.collection_was_cleared) {
-                        m_logger->log(util::LogCategory::notification, util::Logger::Level::trace,
-                                      "   collection cleared");
-                    }
-                    else {
-                        auto log = [this](const char* change, const IndexSet& index_set) {
-                            if (auto cnt = index_set.count()) {
-                                std::ostringstream ostr;
-                                bool first = true;
-                                for (auto [a, b] : index_set) {
-                                    if (!first)
-                                        ostr << ',';
-                                    if (b > a + 1) {
-                                        ostr << '[' << a << ',' << b - 1 << ']';
-                                    }
-                                    else {
-                                        ostr << a;
-                                    }
-                                    first = false;
-                                }
-                                m_logger->log(util::LogCategory::notification, util::Logger::Level::trace,
-                                              "   %1 %2: %3", cnt, change, ostr.str().c_str());
-                            }
-                        };
-                        log("deletions", changes.deletions);
-                        log("insertions", changes.insertions);
-                        log("modifications", changes.modifications);
-                    }
-                }
-            }
-        }
+        log_changeset(m_logger.get(), changes, m_description, elapsed);
         cb.after(changes);
     });
 }
@@ -529,3 +537,24 @@ void NotifierPackage::after_advance()
     for (auto& notifier : m_notifiers)
         notifier->after_advance();
 }
+
+NotifierRunLogger::NotifierRunLogger(util::Logger* logger, std::string_view name, std::string_view description)
+    : m_logger(logger)
+    , m_name(name)
+    , m_description(description)
+{
+    if (logger && logger->would_log(util::Logger::Level::debug)) {
+        m_logger = logger;
+        m_start = std::chrono::steady_clock::now();
+    }
+}
+
+NotifierRunLogger::~NotifierRunLogger()
+{
+    using namespace std::chrono;
+    if (m_logger) {
+        auto now = steady_clock::now();
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "%1 %2 ran in %3 us", m_name,
+                      m_description, duration_cast<microseconds>(now - m_start).count());
+    }
+}
diff --git a/src/realm/object-store/impl/collection_notifier.hpp b/src/realm/object-store/impl/collection_notifier.hpp
@@ -381,6 +381,18 @@ class NotifierPackage {
     RealmCoordinator* m_coordinator = nullptr;
 };
 
+class NotifierRunLogger {
+public:
+    NotifierRunLogger(util::Logger* logger, std::string_view name, std::string_view description);
+    ~NotifierRunLogger();
+
+private:
+    util::Logger* m_logger;
+    std::string_view m_name;
+    std::string_view m_description;
+    std::chrono::steady_clock::time_point m_start;
+};
+
 } // namespace realm::_impl
 
 #endif /* REALM_BACKGROUND_COLLECTION_HPP */
diff --git a/src/realm/object-store/impl/list_notifier.cpp b/src/realm/object-store/impl/list_notifier.cpp
@@ -33,7 +33,7 @@ ListNotifier::ListNotifier(std::shared_ptr<Realm> realm, CollectionBase const& l
     , m_prev_size(list.size())
 {
     attach(list);
-    if (m_logger) {
+    if (m_logger && m_logger->would_log(util::Logger::Level::debug)) {
         auto path = m_list->get_short_path();
         auto prop_name = m_list->get_table()->get_column_name(path[0].get_col_key());
         path[0] = PathElement(prop_name);
@@ -94,16 +94,7 @@ bool ListNotifier::do_add_required_change_info(TransactionChangeInfo& info)
 
 void ListNotifier::run()
 {
-    using namespace std::chrono;
-    auto t1 = steady_clock::now();
-    util::ScopeExit cleanup([&]() noexcept {
-        m_run_time_point = steady_clock::now();
-        if (m_logger) {
-            m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
-                          "ListNotifier %1 did run in %2 us", m_description,
-                          duration_cast<microseconds>(m_run_time_point - t1).count());
-        }
-    });
+    NotifierRunLogger log(m_logger.get(), "ListNotifier", m_description);
 
     if (!m_list || !m_list->is_attached()) {
         // List was deleted, so report all of the rows being removed if this is
diff --git a/src/realm/object-store/impl/object_notifier.cpp b/src/realm/object-store/impl/object_notifier.cpp
@@ -64,16 +64,7 @@ void ObjectNotifier::run()
 {
     if (!m_table || !m_info)
         return;
-    using namespace std::chrono;
-    auto t1 = steady_clock::now();
-    util::ScopeExit cleanup([&]() noexcept {
-        m_run_time_point = steady_clock::now();
-        if (m_logger) {
-            m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
-                          "ObjectNotifier %1 did run in %2 us", m_description,
-                          duration_cast<microseconds>(m_run_time_point - t1).count());
-        }
-    });
+    NotifierRunLogger log(m_logger.get(), "ObjectNotifier", m_description);
 
     auto it = m_info->tables.find(m_table->get_key());
     if (it != m_info->tables.end() && it->second.deletions_contains(m_obj_key)) {
diff --git a/src/realm/object-store/impl/results_notifier.cpp b/src/realm/object-store/impl/results_notifier.cpp
@@ -65,12 +65,12 @@ ResultsNotifier::ResultsNotifier(Results& target)
     , m_target_is_in_table_order(target.is_in_table_order())
 {
     if (m_logger) {
-        m_description = std::string("'") + std::string(m_query->get_table()->get_class_name()) + std::string("'");
+        m_description = "'" + std::string(m_query->get_table()->get_class_name()) + "'";
         if (m_query->has_conditions()) {
             m_description += " where \"";
             m_description += m_query->get_description_safe() + "\"";
         }
-        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Creating ResultsNotifier for ",
+        m_logger->log(util::LogCategory::notification, util::Logger::Level::debug, "Creating ResultsNotifier for %1",
                       m_description);
     }
     reattach();
@@ -151,20 +151,10 @@ void ResultsNotifier::calculate_changes()
 
 void ResultsNotifier::run()
 {
-    using namespace std::chrono;
+    NotifierRunLogger log(m_logger.get(), "ResultsNotifier", m_description);
 
     REALM_ASSERT(m_info || !has_run());
 
-    auto t1 = steady_clock::now();
-    util::ScopeExit cleanup([&]() noexcept {
-        m_run_time_point = steady_clock::now();
-        if (m_logger) {
-            m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
-                          "ResultsNotifier %1 did run in %2 us", m_description,
-                          duration_cast<microseconds>(m_run_time_point - t1).count());
-        }
-    });
-
     // Table's been deleted, so report all objects as deleted
     if (!m_query->get_table()) {
         m_change = {};
@@ -278,7 +268,7 @@ ListResultsNotifier::ListResultsNotifier(Results& target)
         auto path = m_list->get_short_path();
         auto prop_name = m_list->get_table()->get_column_name(path[0].get_col_key());
         path[0] = PathElement(prop_name);
-        std::string sort_order;
+        std::string_view sort_order = "";
         if (m_sort_order) {
             sort_order = *m_sort_order ? " sorted ascending" : " sorted descending";
         }
@@ -358,17 +348,6 @@ void ListResultsNotifier::calculate_changes()
 
 void ListResultsNotifier::run()
 {
-    using namespace std::chrono;
-    auto t1 = steady_clock::now();
-    util::ScopeExit cleanup([&]() noexcept {
-        m_run_time_point = steady_clock::now();
-        if (m_logger) {
-            m_logger->log(util::LogCategory::notification, util::Logger::Level::debug,
-                          "ListResultsNotifier %1 did run in %2 us", m_description,
-                          duration_cast<microseconds>(m_run_time_point - t1).count());
-        }
-    });
-
     if (!m_list || !m_list->is_attached()) {
         // List was deleted, so report all of the rows being removed
         m_change = {};
@@ -379,10 +358,11 @@ void ListResultsNotifier::run()
     }
 
     if (!need_to_run()) {
-        cleanup.cancel();
         return;
     }
 
+    NotifierRunLogger log(m_logger.get(), "ListResultsNotifier", m_description);
+
     m_run_indices = std::vector<size_t>();
     if (m_distinct)
         m_list->distinct(*m_run_indices, m_sort_order);
