diff --git a/base/Android.bp b/base/Android.bp index 894ad6c50..58af2eb8f 100644 --- a/base/Android.bp +++ b/base/Android.bp @@ -157,6 +157,7 @@ cc_test { "errors_test.cpp", "expected_test.cpp", "file_test.cpp", + "logging_splitters_test.cpp", "logging_test.cpp", "macros_test.cpp", "mapped_file_test.cpp", diff --git a/base/include/android-base/logging.h b/base/include/android-base/logging.h index accc225db..26827fb83 100644 --- a/base/include/android-base/logging.h +++ b/base/include/android-base/logging.h @@ -118,8 +118,10 @@ void DefaultAborter(const char* abort_message); void SetDefaultTag(const std::string& tag); -// We expose this even though it is the default because a user that wants to -// override the default log buffer will have to construct this themselves. +// The LogdLogger sends chunks of up to ~4000 bytes at a time to logd. It does not prevent other +// threads from writing to logd between sending each chunk, so other threads may interleave their +// messages. If preventing interleaving is required, then a custom logger that takes a lock before +// calling this logger should be provided. class LogdLogger { public: explicit LogdLogger(LogId default_log_id = android::base::MAIN); diff --git a/base/logging.cpp b/base/logging.cpp index 3c73fea1a..6e9c67fc4 100644 --- a/base/logging.cpp +++ b/base/logging.cpp @@ -61,6 +61,7 @@ #include #include "liblog_symbols.h" +#include "logging_splitters.h" namespace android { namespace base { @@ -190,11 +191,6 @@ static int32_t LogSeverityToPriority(LogSeverity severity) { } } -static std::mutex& LoggingLock() { - static auto& logging_lock = *new std::mutex(); - return logging_lock; -} - static LogFunction& Logger() { #ifdef __ANDROID__ static auto& logger = *new LogFunction(LogdLogger()); @@ -239,8 +235,8 @@ static bool gInitialized = false; static LogSeverity gMinimumLogSeverity = INFO; #if defined(__linux__) -void KernelLogger(android::base::LogId, android::base::LogSeverity severity, - const char* tag, const char*, unsigned int, const char* msg) { +static void KernelLogLine(const char* msg, int length, android::base::LogSeverity severity, + const char* tag) { // clang-format off static constexpr int kLogSeverityToKernelLogLevel[] = { [android::base::VERBOSE] = 7, // KERN_DEBUG (there is no verbose kernel log @@ -265,7 +261,7 @@ void KernelLogger(android::base::LogId, android::base::LogSeverity severity, // TODO: should we automatically break up long lines into multiple lines? // Or we could log but with something like "..." at the end? char buf[1024]; - size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %s\n", level, tag, msg); + size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %.*s\n", level, tag, length, msg); if (size > sizeof(buf)) { size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n", level, tag, size); @@ -276,6 +272,11 @@ void KernelLogger(android::base::LogId, android::base::LogSeverity severity, iov[0].iov_len = size; TEMP_FAILURE_RETRY(writev(klog_fd, iov, 1)); } + +void KernelLogger(android::base::LogId, android::base::LogSeverity severity, const char* tag, + const char*, unsigned int, const char* full_message) { + SplitByLines(full_message, KernelLogLine, severity, tag); +} #endif void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file, unsigned int line, @@ -288,21 +289,10 @@ void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file #else localtime_r(&t, &now); #endif + auto output_string = + StderrOutputGenerator(now, getpid(), GetThreadId(), severity, tag, file, line, message); - char timestamp[32]; - strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now); - - static const char log_characters[] = "VDIWEFF"; - static_assert(arraysize(log_characters) - 1 == FATAL + 1, - "Mismatch in size of log_characters and values in LogSeverity"); - char severity_char = log_characters[severity]; - if (file != nullptr) { - fprintf(stderr, "%s %c %s %5d %5" PRIu64 " %s:%u] %s\n", tag ? tag : "nullptr", severity_char, - timestamp, getpid(), GetThreadId(), file, line, message); - } else { - fprintf(stderr, "%s %c %s %5d %5" PRIu64 " %s\n", tag ? tag : "nullptr", severity_char, - timestamp, getpid(), GetThreadId(), message); - } + fputs(output_string.c_str(), stderr); } void StdioLogger(LogId, LogSeverity severity, const char* /*tag*/, const char* /*file*/, @@ -324,26 +314,9 @@ void DefaultAborter(const char* abort_message) { abort(); } - -LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) { -} - -void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, - const char* file, unsigned int line, - const char* message) { - int32_t priority = LogSeverityToPriority(severity); - if (id == DEFAULT) { - id = default_log_id_; - } - +static void LogdLogChunk(LogId id, LogSeverity severity, const char* tag, const char* message) { int32_t lg_id = LogIdTolog_id_t(id); - - char log_message_with_file[4068]; // LOGGER_ENTRY_MAX_PAYLOAD, not available in the NDK. - if (priority == ANDROID_LOG_FATAL && file != nullptr) { - snprintf(log_message_with_file, sizeof(log_message_with_file), "%s:%u] %s", file, line, - message); - message = log_message_with_file; - } + int32_t priority = LogSeverityToPriority(severity); static auto& liblog_functions = GetLibLogFunctions(); if (liblog_functions) { @@ -355,6 +328,17 @@ void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, } } +LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) {} + +void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, const char* file, + unsigned int line, const char* message) { + if (id == DEFAULT) { + id = default_log_id_; + } + + SplitByLogdChunks(id, severity, tag, file, line, message, LogdLogChunk); +} + void InitLogging(char* argv[], LogFunction&& logger, AbortFunction&& aborter) { SetLogger(std::forward(logger)); SetAborter(std::forward(aborter)); @@ -515,26 +499,8 @@ LogMessage::~LogMessage() { #endif } - { - // Do the actual logging with the lock held. - std::lock_guard lock(LoggingLock()); - if (msg.find('\n') == std::string::npos) { - LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(), - msg.c_str()); - } else { - msg += '\n'; - size_t i = 0; - while (i < msg.size()) { - size_t nl = msg.find('\n', i); - msg[nl] = '\0'; - LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(), - &msg[i]); - // Undo the zero-termination so we can give the complete message to the aborter. - msg[nl] = '\n'; - i = nl + 1; - } - } - } + LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(), + msg.c_str()); // Abort if necessary. if (data_->GetSeverity() == FATAL) { diff --git a/base/logging_splitters.h b/base/logging_splitters.h new file mode 100644 index 000000000..2ec2b205d --- /dev/null +++ b/base/logging_splitters.h @@ -0,0 +1,185 @@ +/* + * Copyright (C) 2020 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include + +#include +#include + +#define LOGGER_ENTRY_MAX_PAYLOAD 4068 // This constant is not in the NDK. + +namespace android { +namespace base { + +// This splits the message up line by line, by calling log_function with a pointer to the start of +// each line and the size up to the newline character. It sends size = -1 for the final line. +template +static void SplitByLines(const char* msg, const F& log_function, Args&&... args) { + const char* newline = strchr(msg, '\n'); + while (newline != nullptr) { + log_function(msg, newline - msg, args...); + msg = newline + 1; + newline = strchr(msg, '\n'); + } + + log_function(msg, -1, args...); +} + +// This splits the message up into chunks that logs can process delimited by new lines. It calls +// log_function with the exact null terminated message that should be sent to logd. +// Note, despite the loops and snprintf's, if severity is not fatal and there are no new lines, +// this function simply calls log_function with msg without any extra overhead. +template +static void SplitByLogdChunks(LogId log_id, LogSeverity severity, const char* tag, const char* file, + unsigned int line, const char* msg, const F& log_function) { + // The maximum size of a payload, after the log header that logd will accept is + // LOGGER_ENTRY_MAX_PAYLOAD, so subtract the other elements in the payload to find the size of + // the string that we can log in each pass. + // The protocol is documented in liblog/README.protocol.md. + // Specifically we subtract a byte for the priority, the length of the tag + its null terminator, + // and an additional byte for the null terminator on the payload. We subtract an additional 32 + // bytes for slack, similar to java/android/util/Log.java. + ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - strlen(tag) - 35; + if (max_size <= 0) { + abort(); + } + // If we're logging a fatal message, we'll append the file and line numbers. + bool add_file = file != nullptr && (severity == FATAL || severity == FATAL_WITHOUT_ABORT); + + std::string file_header; + if (add_file) { + file_header = StringPrintf("%s:%u] ", file, line); + } + int file_header_size = file_header.size(); + + __attribute__((uninitialized)) char logd_chunk[max_size + 1]; + ptrdiff_t chunk_position = 0; + + auto call_log_function = [&]() { + log_function(log_id, severity, tag, logd_chunk); + chunk_position = 0; + }; + + auto write_to_logd_chunk = [&](const char* message, int length) { + int size_written = 0; + const char* new_line = chunk_position > 0 ? "\n" : ""; + if (add_file) { + size_written = snprintf(logd_chunk + chunk_position, sizeof(logd_chunk) - chunk_position, + "%s%s%.*s", new_line, file_header.c_str(), length, message); + } else { + size_written = snprintf(logd_chunk + chunk_position, sizeof(logd_chunk) - chunk_position, + "%s%.*s", new_line, length, message); + } + + // This should never fail, if it does and we set size_written to 0, which will skip this line + // and move to the next one. + if (size_written < 0) { + size_written = 0; + } + chunk_position += size_written; + }; + + const char* newline = strchr(msg, '\n'); + while (newline != nullptr) { + // If we have data in the buffer and this next line doesn't fit, write the buffer. + if (chunk_position != 0 && chunk_position + (newline - msg) + 1 + file_header_size > max_size) { + call_log_function(); + } + + // Otherwise, either the next line fits or we have any empty buffer and too large of a line to + // ever fit, in both cases, we add it to the buffer and continue. + write_to_logd_chunk(msg, newline - msg); + + msg = newline + 1; + newline = strchr(msg, '\n'); + } + + // If we have left over data in the buffer and we can fit the rest of msg, add it to the buffer + // then write the buffer. + if (chunk_position != 0 && + chunk_position + static_cast(strlen(msg)) + 1 + file_header_size <= max_size) { + write_to_logd_chunk(msg, -1); + call_log_function(); + } else { + // If the buffer is not empty and we can't fit the rest of msg into it, write its contents. + if (chunk_position != 0) { + call_log_function(); + } + // Then write the rest of the msg. + if (add_file) { + snprintf(logd_chunk, sizeof(logd_chunk), "%s%s", file_header.c_str(), msg); + log_function(log_id, severity, tag, logd_chunk); + } else { + log_function(log_id, severity, tag, msg); + } + } +} + +static std::pair CountSizeAndNewLines(const char* message) { + int size = 0; + int new_lines = 0; + while (*message != '\0') { + size++; + if (*message == '\n') { + ++new_lines; + } + ++message; + } + return {size, new_lines}; +} + +// This adds the log header to each line of message and returns it as a string intended to be +// written to stderr. +static std::string StderrOutputGenerator(const struct tm& now, int pid, uint64_t tid, + LogSeverity severity, const char* tag, const char* file, + unsigned int line, const char* message) { + char timestamp[32]; + strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now); + + static const char log_characters[] = "VDIWEFF"; + static_assert(arraysize(log_characters) - 1 == FATAL + 1, + "Mismatch in size of log_characters and values in LogSeverity"); + char severity_char = log_characters[severity]; + std::string line_prefix; + if (file != nullptr) { + line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " %s:%u] ", tag ? tag : "nullptr", + severity_char, timestamp, pid, tid, file, line); + } else { + line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " ", tag ? tag : "nullptr", severity_char, + timestamp, pid, tid); + } + + auto [size, new_lines] = CountSizeAndNewLines(message); + std::string output_string; + output_string.reserve(size + new_lines * line_prefix.size() + 1); + + auto concat_lines = [&](const char* message, int size) { + output_string.append(line_prefix); + if (size == -1) { + output_string.append(message); + } else { + output_string.append(message, size); + } + output_string.append("\n"); + }; + SplitByLines(message, concat_lines); + return output_string; +} + +} // namespace base +} // namespace android diff --git a/base/logging_splitters_test.cpp b/base/logging_splitters_test.cpp new file mode 100644 index 000000000..679d19ed1 --- /dev/null +++ b/base/logging_splitters_test.cpp @@ -0,0 +1,325 @@ +/* + * Copyright (C) 2020 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "logging_splitters.h" + +#include +#include + +#include +#include + +namespace android { +namespace base { + +void TestNewlineSplitter(const std::string& input, + const std::vector& expected_output) { + std::vector output; + auto logger_function = [&](const char* msg, int length) { + if (length == -1) { + output.push_back(msg); + } else { + output.push_back(std::string(msg, length)); + } + }; + SplitByLines(input.c_str(), logger_function); + + EXPECT_EQ(expected_output, output); +} + +TEST(logging_splitters, NewlineSplitter_EmptyString) { + TestNewlineSplitter("", std::vector{""}); +} + +TEST(logging_splitters, NewlineSplitter_BasicString) { + TestNewlineSplitter("normal string", std::vector{"normal string"}); +} + +TEST(logging_splitters, NewlineSplitter_ormalBasicStringTrailingNewline) { + TestNewlineSplitter("normal string\n", std::vector{"normal string", ""}); +} + +TEST(logging_splitters, NewlineSplitter_MultilineTrailing) { + TestNewlineSplitter("normal string\nsecond string\nthirdstring", + std::vector{"normal string", "second string", "thirdstring"}); +} + +TEST(logging_splitters, NewlineSplitter_MultilineTrailingNewline) { + TestNewlineSplitter( + "normal string\nsecond string\nthirdstring\n", + std::vector{"normal string", "second string", "thirdstring", ""}); +} + +TEST(logging_splitters, NewlineSplitter_MultilineEmbeddedNewlines) { + TestNewlineSplitter( + "normal string\n\n\nsecond string\n\nthirdstring\n", + std::vector{"normal string", "", "", "second string", "", "thirdstring", ""}); +} + +void TestLogdChunkSplitter(const std::string& tag, const std::string& file, + const std::string& input, + const std::vector& expected_output) { + std::vector output; + auto logger_function = [&](LogId, LogSeverity, const char*, const char* msg) { + output.push_back(msg); + }; + + SplitByLogdChunks(MAIN, FATAL, tag.c_str(), file.empty() ? nullptr : file.c_str(), 1000, + input.c_str(), logger_function); + + auto return_lengths = [&] { + std::string sizes; + sizes += "expected_output sizes:"; + for (const auto& string : expected_output) { + sizes += " " + std::to_string(string.size()); + } + sizes += "\noutput sizes:"; + for (const auto& string : output) { + sizes += " " + std::to_string(string.size()); + } + return sizes; + }; + + EXPECT_EQ(expected_output, output) << return_lengths(); +} + +TEST(logging_splitters, LogdChunkSplitter_EmptyString) { + TestLogdChunkSplitter("tag", "", "", std::vector{""}); +} + +TEST(logging_splitters, LogdChunkSplitter_BasicString) { + TestLogdChunkSplitter("tag", "", "normal string", std::vector{"normal string"}); +} + +TEST(logging_splitters, LogdChunkSplitter_NormalBasicStringTrailingNewline) { + TestLogdChunkSplitter("tag", "", "normal string\n", std::vector{"normal string\n"}); +} + +TEST(logging_splitters, LogdChunkSplitter_MultilineTrailing) { + TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring", + std::vector{"normal string\nsecond string\nthirdstring"}); +} + +TEST(logging_splitters, LogdChunkSplitter_MultilineTrailingNewline) { + TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring\n", + std::vector{"normal string\nsecond string\nthirdstring\n"}); +} + +TEST(logging_splitters, LogdChunkSplitter_MultilineEmbeddedNewlines) { + TestLogdChunkSplitter( + "tag", "", "normal string\n\n\nsecond string\n\nthirdstring\n", + std::vector{"normal string\n\n\nsecond string\n\nthirdstring\n"}); +} + +// This test should return the same string, the logd logger itself will truncate down to size. +// This has historically been the behavior both in libbase and liblog. +TEST(logging_splitters, LogdChunkSplitter_HugeLineNoNewline) { + auto long_string = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'x'); + ASSERT_EQ(LOGGER_ENTRY_MAX_PAYLOAD, static_cast(long_string.size())); + + TestLogdChunkSplitter("tag", "", long_string, std::vector{long_string}); +} + +std::string ReduceToMaxSize(const std::string& tag, const std::string& string) { + return string.substr(0, LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35); +} + +TEST(logging_splitters, LogdChunkSplitter_MultipleHugeLineNoNewline) { + auto long_string_x = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'x'); + auto long_string_y = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'y'); + auto long_string_z = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'z'); + + auto long_strings = long_string_x + '\n' + long_string_y + '\n' + long_string_z; + + std::string tag = "tag"; + std::vector expected = {ReduceToMaxSize(tag, long_string_x), ReduceToMaxSize(tag, long_string_y), + long_string_z}; + + TestLogdChunkSplitter(tag, "", long_strings, expected); +} + +// With a ~4k buffer, we should print 2 long strings per logger call. +TEST(logging_splitters, LogdChunkSplitter_Multiple2kLines) { + std::vector expected = { + std::string(2000, 'a') + '\n' + std::string(2000, 'b'), + std::string(2000, 'c') + '\n' + std::string(2000, 'd'), + std::string(2000, 'e') + '\n' + std::string(2000, 'f'), + }; + + auto long_strings = Join(expected, '\n'); + + TestLogdChunkSplitter("tag", "", long_strings, expected); +} + +TEST(logging_splitters, LogdChunkSplitter_ExactSizedLines) { + const char* tag = "tag"; + ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - strlen(tag) - 35; + auto long_string_a = std::string(max_size, 'a'); + auto long_string_b = std::string(max_size, 'b'); + auto long_string_c = std::string(max_size, 'c'); + + auto long_strings = long_string_a + '\n' + long_string_b + '\n' + long_string_c; + + TestLogdChunkSplitter(tag, "", long_strings, + std::vector{long_string_a, long_string_b, long_string_c}); +} + +TEST(logging_splitters, LogdChunkSplitter_UnderEqualOver) { + std::string tag = "tag"; + ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35; + + auto first_string_size = 1000; + auto first_string = std::string(first_string_size, 'a'); + auto second_string_size = max_size - first_string_size - 1; + auto second_string = std::string(second_string_size, 'b'); + + auto exact_string = std::string(max_size, 'c'); + + auto large_string = std::string(max_size + 50, 'd'); + + auto final_string = std::string("final string!\n\nfinal \n \n final \n"); + + std::vector expected = {first_string + '\n' + second_string, exact_string, + ReduceToMaxSize(tag, large_string), final_string}; + + std::vector input_strings = {first_string + '\n' + second_string, exact_string, large_string, + final_string}; + auto long_strings = Join(input_strings, '\n'); + + TestLogdChunkSplitter(tag, "", long_strings, expected); +} + +TEST(logging_splitters, LogdChunkSplitter_WithFile) { + std::string tag = "tag"; + std::string file = "/path/to/myfile.cpp"; + int line = 1000; + auto file_header = StringPrintf("%s:%d] ", file.c_str(), line); + ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35; + + auto first_string_size = 1000; + auto first_string = std::string(first_string_size, 'a'); + auto second_string_size = max_size - first_string_size - 1 - 2 * file_header.size(); + auto second_string = std::string(second_string_size, 'b'); + + auto exact_string = std::string(max_size - file_header.size(), 'c'); + + auto large_string = std::string(max_size + 50, 'd'); + + auto final_string = std::string("final string!"); + + std::vector expected = { + file_header + first_string + '\n' + file_header + second_string, file_header + exact_string, + file_header + ReduceToMaxSize(file_header + tag, large_string), file_header + final_string}; + + std::vector input_strings = {first_string + '\n' + second_string, exact_string, large_string, + final_string}; + auto long_strings = Join(input_strings, '\n'); + + TestLogdChunkSplitter(tag, file, long_strings, expected); +} + +// We set max_size based off of tag, so if it's too large, the buffer will be sized wrong. +// We could recover from this, but it's certainly an error for someone to attempt to use a tag this +// large, so we abort instead. +TEST(logging_splitters, LogdChunkSplitter_TooLongTag) { + auto long_tag = std::string(5000, 'x'); + auto logger_function = [](LogId, LogSeverity, const char*, const char*) {}; + ASSERT_DEATH( + SplitByLogdChunks(MAIN, ERROR, long_tag.c_str(), nullptr, 0, "message", logger_function), ""); +} + +// We do handle excessively large file names correctly however. +TEST(logging_splitters, LogdChunkSplitter_TooLongFile) { + auto long_file = std::string(5000, 'x'); + std::string tag = "tag"; + + std::vector expected = {ReduceToMaxSize(tag, long_file), ReduceToMaxSize(tag, long_file)}; + + TestLogdChunkSplitter(tag, long_file, "can't see me\nor me", expected); +} + +void TestStderrOutputGenerator(const char* tag, const char* file, int line, const char* message, + const std::string& expected) { + // All log messages will show "01-01 00:00:00" + struct tm now = { + .tm_sec = 0, + .tm_min = 0, + .tm_hour = 0, + .tm_mday = 1, + .tm_mon = 0, + .tm_year = 1970, + }; + + int pid = 1234; // All log messages will have 1234 for their PID. + uint64_t tid = 4321; // All log messages will have 4321 for their TID. + + auto result = StderrOutputGenerator(now, pid, tid, ERROR, tag, file, line, message); + EXPECT_EQ(expected, result); +} + +TEST(logging_splitters, StderrOutputGenerator_Basic) { + TestStderrOutputGenerator(nullptr, nullptr, 0, "simple message", + "nullptr E 01-01 00:00:00 1234 4321 simple message\n"); + TestStderrOutputGenerator("tag", nullptr, 0, "simple message", + "tag E 01-01 00:00:00 1234 4321 simple message\n"); + TestStderrOutputGenerator( + "tag", "/path/to/some/file", 0, "simple message", + "tag E 01-01 00:00:00 1234 4321 /path/to/some/file:0] simple message\n"); +} + +TEST(logging_splitters, StderrOutputGenerator_NewlineTagAndFile) { + TestStderrOutputGenerator("tag\n\n", nullptr, 0, "simple message", + "tag\n\n E 01-01 00:00:00 1234 4321 simple message\n"); + TestStderrOutputGenerator( + "tag", "/path/to/some/file\n\n", 0, "simple message", + "tag E 01-01 00:00:00 1234 4321 /path/to/some/file\n\n:0] simple message\n"); +} + +TEST(logging_splitters, StderrOutputGenerator_TrailingNewLine) { + TestStderrOutputGenerator( + "tag", nullptr, 0, "simple message\n", + "tag E 01-01 00:00:00 1234 4321 simple message\ntag E 01-01 00:00:00 1234 4321 \n"); +} + +TEST(logging_splitters, StderrOutputGenerator_MultiLine) { + const char* expected_result = + "tag E 01-01 00:00:00 1234 4321 simple message\n" + "tag E 01-01 00:00:00 1234 4321 \n" + "tag E 01-01 00:00:00 1234 4321 \n" + "tag E 01-01 00:00:00 1234 4321 another message \n" + "tag E 01-01 00:00:00 1234 4321 \n" + "tag E 01-01 00:00:00 1234 4321 final message \n" + "tag E 01-01 00:00:00 1234 4321 \n" + "tag E 01-01 00:00:00 1234 4321 \n" + "tag E 01-01 00:00:00 1234 4321 \n"; + + TestStderrOutputGenerator("tag", nullptr, 0, + "simple message\n\n\nanother message \n\n final message \n\n\n", + expected_result); +} + +TEST(logging_splitters, StderrOutputGenerator_MultiLineLong) { + auto long_string_a = std::string(4000, 'a'); + auto long_string_b = std::string(4000, 'b'); + + auto message = long_string_a + '\n' + long_string_b; + auto expected_result = "tag E 01-01 00:00:00 1234 4321 " + long_string_a + '\n' + + "tag E 01-01 00:00:00 1234 4321 " + long_string_b + '\n'; + TestStderrOutputGenerator("tag", nullptr, 0, message.c_str(), expected_result); +} + +} // namespace base +} // namespace android diff --git a/base/logging_test.cpp b/base/logging_test.cpp index 3a453e66c..593e2c100 100644 --- a/base/logging_test.cpp +++ b/base/logging_test.cpp @@ -24,8 +24,10 @@ #include #include +#include #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 @@ TEST(logging, LOG_FATAL_ABORTER_MESSAGE) { 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 @@ TEST(logging, StdioLogger) { // 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 +}