RCORE-2234 Crash in dart due to debug output when app is being torn down #7985

michael-wb · 2024-08-14T17:16:13Z

What, How & Why?

The static mutex used to add thread safety to the StderrLogger was sometimes causing a crash on app exit when the mutex was destroyed before the stderr logger shared pointer instance was deallocated.

These changes remove the mutex altogether and use the inherent thread safety in std::cerr to prevent commingling the debug messages.

Fixes #7969

☑️ ToDos

📝 Changelog update
~~[ ] 🚦 Tests (or not relevant)~~
~~[ ] C-API, if public C++ API changed~~
~~[ ] bindgen/spec.yml, if public C++ API changed~~

coveralls-official · 2024-08-14T19:00:46Z

Pull Request Test Coverage Report for Build michael.wilkersonbarker_1354

Details

1 of 1 (100.0%) changed or added relevant line in 1 file are covered.
No unchanged relevant lines lost coverage.
Overall first build on mwb/logger-crash-during-teardown at 91.127%

Totals
Change from base Build 2575:	91.1%
Covered Lines:	217450
Relevant Lines:	238624

💛 - Coveralls

…crash-during-teardown

michael-wb · 2024-08-16T15:36:24Z

src/realm/util/logger.cpp

+void StderrLogger::do_write(std::string&& output)
+{
+    REALM_ASSERT(m_log_mutex);
+    // Lock the mutex to avoid comingling the logger output messages
+    std::lock_guard l(*m_log_mutex.get());
    // std::cerr is unbuffered, so no need to flush
-    std::cerr << cat.get_name() << " - " << get_level_prefix(level) << message << '\n'; // Throws
+    std::cerr << output << std::endl; // Throws
 }


This was added so the StderrLogger and the TimestampStderrLogger use the same static mutex when writing to stderr.

jbreams · 2024-08-16T15:43:28Z

src/realm/util/logger.cpp

+void StderrLogger::do_write(std::string&& output)
+{
+    REALM_ASSERT(m_log_mutex);
+    // Lock the mutex to avoid comingling the logger output messages


something i've never understood is why we need this mutex at all. std::cerr is threadsafe on its own. if the C++ standard library is working correctly, you should never see comingling of logger output messages to stderr.

Removed the mutex - a single << call to std::cerr is thread safe, so output message is created first and then pushed to stderr as a single string.

to be clear, i meant this as a question rather than a statement. is the reason we added the mutex here because we were seeing interleaving or something else?

There was some interleaving in the past during the tests. For std::cerr, each individual streaming operator call is thread safe, but chained operators are not, allowing context changes to happen before the entire message is printed.
e.g., std::cerr << "string a" << "string b"; ==> std::cerr << "string a"; std::cerr << "string b";

But unfortunately, MacOS TSAN is not happy with writing to std::cerr from two threads, but it is fine with fprintf() and supposedly it is faster then std::cerr. I updated StderrLogger to use fprintf() instead.

jbreams · 2024-08-16T15:43:46Z

src/realm/util/logger.cpp

    // std::cerr is unbuffered, so no need to flush
-    std::cerr << cat.get_name() << " - " << get_level_prefix(level) << message << '\n'; // Throws
+    std::cerr << output << std::endl; // Throws


the comment right above says that you don't need to do std::endl because cerr is unbuffered.

Sorry, bad habit - reverted to '\n'

jbreams · 2024-08-16T15:44:25Z

test/object-store/audit.cpp

@@ -52,13 +52,6 @@ using namespace std::string_literals;
 using Catch::Matchers::StartsWith;
 using nlohmann::json;

-static auto audit_logger =


why did this need to change?

I was trying to remove the instances of static loggers, but it doesn't matter here - reverted the change

jbreams · 2024-08-16T15:49:33Z

src/realm/util/timestamp_logger.hpp

@@ -9,15 +9,15 @@
 namespace realm {
 namespace util {

-class TimestampStderrLogger : public Logger {
+class TimestampStderrLogger : public StderrLogger {


It looks like the TimestampStderrLogger is completely unused outside of tests. Can we just remove it?

jbreams · 2024-08-16T15:50:46Z

src/realm/util/logger.cpp

+
+void StderrLogger::do_write(std::string&& output)
+{
+    REALM_ASSERT(m_log_mutex);


When could this assert ever be false?

jbreams · 2024-08-16T17:17:01Z

as a more general high level question - did we get to the bottom of why this was crashing in dart? destruction of statics is undefined behavior, but generally i think we've seen that happen while the process is exiting, which implies dart maybe isn't tearing realm down cleanly since there are threads out there still running while the process exits? do we know what's actually going on here?

michael-wb · 2024-08-16T17:46:19Z

as a more general high level question - did we get to the bottom of why this was crashing in dart? destruction of statics is undefined behavior, but generally i think we've seen that happen while the process is exiting, which implies dart maybe isn't tearing realm down cleanly since there are threads out there still running while the process exits? do we know what's actually going on here?

I tried reproducing the issue with several versions of realm-dart, but I was never able to reproduce it in a macos app or in the ios simulator. From the stack trace, however, I believe it is clear that the crash is occurring because the static mutex is no longer valid when DB::close_internal() tries to print a log message at the detail level when a realm object is being closed.

jbreams · 2024-08-19T13:46:23Z

Tldr - bug fixes should be scoped narrowly, especially if we haven't been able to reproduce the crash. Going out and refactoring things as part of a speculative bugfix is how you make more bugs.

It's pretty disappointing that we never reproduced this despite having a sample project that demonstrates the problem. I think it's a good guess that this static mutex is being destroyed before all the databases have been torn down and that's causing problems, but it would be great to know whether that behavior in itself is a bug or if this is just weird behavior we'll have to work around.

All that said, I think the first approach of using a std::shared_ptr was valid. A simpler solution could have been to just treat this mutex the way we treat the default logger mutex and other static mutexes we really want to live forever by doing auto& stderr_logger_mutex = *new std::mutex;. I don't think we should refactor the StderrLogger with the do_write(std::string&&) method because that introduces a new allocation/copy in a potentially pretty hot path. I don't think we need to touch tests that are passing. I think the timestamp logger can just be left alone.

I also think it's fine to keep using std::cerr and have a mutex to synchronize access to it, I just wanted to understand why we needed it. The answer that we were seeing interpolation is totally valid. It looks like it was added during a general CI improvements PR, so I wasn't sure the context for it being added.

michael-wb · 2024-08-19T14:31:52Z

Understood @jbreams - I looked further into how the realm shared lib was being loaded/unloaded. The realm library is loaded the first time the realmLib global variable is used (e.g., for calling a CAPI function), but it is never explicitly unloaded, so it is up to the Dart to decide when the realmLib object is destroyed and the library is unloaded. Being able to reproduce this may be dependent on the version of the dart compiler used which could change the order in which the library is unloaded.

I see that JS also has had some logger crashes (which may be due to the all issue) and I reached out to Kræn to see if it is still happening with the fix for PR #7934. If it doesn't fix the issue, then perhaps the JS SDK is also being affected by the mutex error and I asked him to see if these changes resolve the issue.

michael-wb · 2024-08-20T12:42:49Z

I was able to reproduce the logger crash yesterday on macos using the Dart SDK 3.4.1, but I have been unable to create a local build of the Dart SDK that is able to compile a macos flutter app to verify the changes in this PR. I can build my flutter app for iOS with my local Dart SDK build, but I haven't been able to reproduce the logger crash on that platform.

I've reached out to the SDK team to see if they can help with my flutter app compile issue.

michael-wb · 2024-08-20T13:24:28Z

Verified these changes address the crash in Dart - I've also reached out to the JS SDK team to see if this also helps with the logger crash they are seeing as well.

jbreams · 2024-08-20T13:49:34Z

So what's going on? Why is the mutex getting destroyed when it is?

jbreams · 2024-08-21T18:04:26Z

src/realm/util/logger.cpp

 void StderrLogger::do_log(const LogCategory& cat, Level level, const std::string& message)
 {
-    static Mutex mutex;
-    LockGuard l(mutex);
+    std::lock_guard l(m_mutex);


Is there a reason we need to capture the global mutex as a member variable reference? Could the whole change for this ticket just be changing this line from static Mutex mutex; to static auto& mutex = *new Mutex; ? Or changing the mutex from a Mutex to a std::mutex as you do above and locking it here without changing any of the headers?

I wasn't sure if there was a risk that the static auto& mutex variable could become invalid so I was saving a local reference to the mutex. Fortunately, this should be defined in the .data region of the application, so actually there shouldn't be any risk of it going away. Just verified with a simple test, so I'll remove the extra reference.

Also verified that the minimal set of logger changes are work fine with the Dart SDK.

Can you expand a bit on how the variable could become invalid and how taking a reference to it would prevent it from becoming invalid? Do you mean there was a risk the heap-allocated mutex could go out-of-scope and be destroyed without anything calling delete on it? How would taking a reference to it prevent that and not just lead to a dangling reference? How does being in the .data section of the image change things here?

I was referring to the global static reference (s_stderr_logger_mutex) variable being destroyed/going away during the app exit. But, since globals/statics like this are symbols defined in the program memory (.bss or .data sections), it will not go away during the lifetime of the app.

…crash-during-teardown

Updated stderrlogger to use a mutex shared_ptr instead of a static

7081339

michael-wb self-assigned this Aug 14, 2024

cla-bot bot added the cla: yes label Aug 14, 2024

Michael Wilkerson-Barker added 2 commits August 14, 2024 13:30

Added missing header

80fa03f

Updated changelog

0037473

Merge branch 'master' of github.com:realm/realm-core into mwb/logger-…

67e6ba4

…crash-during-teardown

michael-wb marked this pull request as ready for review August 16, 2024 00:01

michael-wb requested review from jedelbo and jbreams August 16, 2024 00:01

jedelbo approved these changes Aug 16, 2024

View reviewed changes

Michael Wilkerson-Barker added 3 commits August 16, 2024 11:14

Removed additional Logger static defines

a50a29c

Merge branch 'master' of github.com:realm/realm-core into mwb/logger-…

a35fdf1

…crash-during-teardown

Fixed changelog after bad merge

75aacbf

michael-wb commented Aug 16, 2024

View reviewed changes

jbreams reviewed Aug 16, 2024

View reviewed changes

Michael Wilkerson-Barker added 2 commits August 16, 2024 12:10

Updates from review - removed StderrLogger mutex - reverted some changes

1e701d1

removed unnecessary include

d805a95

michael-wb requested a review from jbreams August 16, 2024 16:38

Michael Wilkerson-Barker added 3 commits August 16, 2024 23:27

changed StderrLogger to use fprintf instead of cerr due to TSAN failure

9fa123b

Removed unused header

1222106

Forgot newline

cb1dab0

Michael Wilkerson-Barker added 2 commits August 19, 2024 11:23

Reverted unnecessary changes, using global pointer mutex reference

406868c

Added missing include

831a504

sync-by-unito bot mentioned this pull request Aug 21, 2024

Crash in dart due to debug output when app is being torn down #7969

Closed

jbreams reviewed Aug 21, 2024

View reviewed changes

Michael Wilkerson-Barker added 2 commits August 21, 2024 15:49

Removed StderrLogger local mutex reference

bf9629e

Merge branch 'master' of github.com:realm/realm-core into mwb/logger-…

1fe996b

…crash-during-teardown

michael-wb requested a review from jbreams August 21, 2024 20:36

jbreams approved these changes Aug 22, 2024

View reviewed changes

michael-wb merged commit 2424fde into master Aug 22, 2024
42 of 43 checks passed

michael-wb deleted the mwb/logger-crash-during-teardown branch August 22, 2024 17:43

github-actions bot mentioned this pull request Aug 30, 2024

Prepare for 14.12.1 #8013

Merged

github-actions bot locked as resolved and limited conversation to collaborators Sep 21, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

RCORE-2234 Crash in dart due to debug output when app is being torn down #7985

RCORE-2234 Crash in dart due to debug output when app is being torn down #7985

michael-wb commented Aug 14, 2024 •

edited

Loading

coveralls-official bot commented Aug 14, 2024 •

edited

Loading

michael-wb Aug 16, 2024

jbreams Aug 16, 2024

michael-wb Aug 16, 2024

jbreams Aug 16, 2024

michael-wb Aug 16, 2024

michael-wb Aug 17, 2024

jbreams Aug 16, 2024

michael-wb Aug 16, 2024

jbreams Aug 16, 2024

michael-wb Aug 16, 2024

jbreams Aug 16, 2024

jbreams Aug 16, 2024

jbreams commented Aug 16, 2024

michael-wb commented Aug 16, 2024

jbreams commented Aug 19, 2024 •

edited

Loading

michael-wb commented Aug 19, 2024

michael-wb commented Aug 20, 2024

michael-wb commented Aug 20, 2024

jbreams commented Aug 20, 2024

jbreams Aug 21, 2024

michael-wb Aug 21, 2024

michael-wb Aug 21, 2024

jbreams Aug 22, 2024

michael-wb Aug 22, 2024

RCORE-2234 Crash in dart due to debug output when app is being torn down #7985

RCORE-2234 Crash in dart due to debug output when app is being torn down #7985

Conversation

michael-wb commented Aug 14, 2024 • edited Loading

What, How & Why?

☑️ ToDos

coveralls-official bot commented Aug 14, 2024 • edited Loading

Pull Request Test Coverage Report for Build michael.wilkersonbarker_1354

Details

💛 - Coveralls

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbreams commented Aug 16, 2024

michael-wb commented Aug 16, 2024

jbreams commented Aug 19, 2024 • edited Loading

michael-wb commented Aug 19, 2024

michael-wb commented Aug 20, 2024

michael-wb commented Aug 20, 2024

jbreams commented Aug 20, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michael-wb commented Aug 14, 2024 •

edited

Loading

coveralls-official bot commented Aug 14, 2024 •

edited

Loading

jbreams commented Aug 19, 2024 •

edited

Loading