base: reimagine line splitting in logger.cpp
Previously, we would split messages by line and call the logger
function for each line. We would hold a lock during this, to ensure
that multiple threads would not interleave their messages.
There are a few problems with this approach:
1) Using a lock is not efficient and is not fork safe
2) With APEX, there is one lock per instance of libbase, so we must
move the lock to a location where all instances can access it, or
perform the line splitting in a way that does not require the lock.
To solve these issues, we reimagine line splitting.
1) We move the lock out of the LogMessage::~LogMessage() and make it
the logger's responsibility to split lines, giving the logger the
option to lock or not.
2) We do not need any locks at all for StderrLogger.
Instead, we generate a single string that contains all of the lines
with their appropriate log header. A single write() call is used
to output this at once.
3) Logd handles log messages with newlines correctly, however it only
accepts up to a maximum size of log message. Therefore we
separate the incoming log message into chunks, delimited by new
lines, up to that maximum size, and send each of those to logd.
Note that this is the strategy used in
android.util.Log.printlns().
This should solve a majority of use cases, since the maximum size
that logd accepts is nearly 4K, while remaining lock free.
If interleaving messages absolutely must be avoided, a lock can
still be used given 1) above.
Bug: 65062446
Bug: 153824050
Test: logging, particularly multi-line stack traces, show correctly
Test: existing and new unit tests
Change-Id: Id0cb5669bee7f912da1e17f7010f0ee4c93be1e3
diff --git a/base/logging_test.cpp b/base/logging_test.cpp
index 3a453e6..593e2c1 100644
--- a/base/logging_test.cpp
+++ b/base/logging_test.cpp
@@ -24,8 +24,10 @@
#include <regex>
#include <string>
+#include <thread>
#include "android-base/file.h"
+#include "android-base/scopeguard.h"
#include "android-base/stringprintf.h"
#include "android-base/test_utils.h"
@@ -596,7 +598,7 @@
CapturedStderr cap;
LOG(FATAL) << "foo\nbar";
- EXPECT_EQ(CountLineAborter::newline_count, 1U + 1U); // +1 for final '\n'.
+ EXPECT_EQ(CountLineAborter::newline_count, 1U);
}
__attribute__((constructor)) void TestLoggingInConstructor() {
@@ -617,3 +619,55 @@
// Whereas ERROR logging includes the program name.
ASSERT_EQ(android::base::Basename(android::base::GetExecutablePath()) + ": err\n", cap_err.str());
}
+
+TEST(logging, ForkSafe) {
+#if !defined(_WIN32)
+ using namespace android::base;
+ SetLogger(
+ [&](LogId, LogSeverity, const char*, const char*, unsigned int, const char*) { sleep(3); });
+
+ auto guard = make_scope_guard([&] {
+#ifdef __ANDROID__
+ SetLogger(LogdLogger());
+#else
+ SetLogger(StderrLogger);
+#endif
+ });
+
+ auto thread = std::thread([] {
+ LOG(ERROR) << "This should sleep for 3 seconds, long enough to fork another process, if there "
+ "is no intervention";
+ });
+ thread.detach();
+
+ auto pid = fork();
+ ASSERT_NE(-1, pid);
+
+ if (pid == 0) {
+ // Reset the logger, so the next message doesn't sleep().
+ SetLogger([](LogId, LogSeverity, const char*, const char*, unsigned int, const char*) {});
+ LOG(ERROR) << "This should succeed in the child, only if libbase is forksafe.";
+ _exit(EXIT_SUCCESS);
+ }
+
+ // Wait for up to 3 seconds for the child to exit.
+ int tries = 3;
+ bool found_child = false;
+ while (tries-- > 0) {
+ auto result = waitpid(pid, nullptr, WNOHANG);
+ EXPECT_NE(-1, result);
+ if (result == pid) {
+ found_child = true;
+ break;
+ }
+ sleep(1);
+ }
+
+ EXPECT_TRUE(found_child);
+
+ // Kill the child if it did not exit.
+ if (!found_child) {
+ kill(pid, SIGKILL);
+ }
+#endif
+}