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
This commit is contained in:
Tom Cherry
parent
efe9defc65
commit
36d31c530d
6 changed files with 597 additions and 64 deletions
|
|
@ -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",
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
|
|
|
|||
|
|
@ -61,6 +61,7 @@
|
|||
#include <android-base/threads.h>
|
||||
|
||||
#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<LogFunction>(logger));
|
||||
SetAborter(std::forward<AbortFunction>(aborter));
|
||||
|
|
@ -515,26 +499,8 @@ LogMessage::~LogMessage() {
|
|||
#endif
|
||||
}
|
||||
|
||||
{
|
||||
// Do the actual logging with the lock held.
|
||||
std::lock_guard<std::mutex> 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) {
|
||||
|
|
|
|||
185
base/logging_splitters.h
Normal file
185
base/logging_splitters.h
Normal file
|
|
@ -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 <inttypes.h>
|
||||
|
||||
#include <android-base/logging.h>
|
||||
#include <android-base/stringprintf.h>
|
||||
|
||||
#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 <typename F, typename... Args>
|
||||
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 <typename F>
|
||||
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<int>(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<int, int> 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
|
||||
325
base/logging_splitters_test.cpp
Normal file
325
base/logging_splitters_test.cpp
Normal file
|
|
@ -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 <string>
|
||||
#include <vector>
|
||||
|
||||
#include <android-base/strings.h>
|
||||
#include <gtest/gtest.h>
|
||||
|
||||
namespace android {
|
||||
namespace base {
|
||||
|
||||
void TestNewlineSplitter(const std::string& input,
|
||||
const std::vector<std::string>& expected_output) {
|
||||
std::vector<std::string> 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<std::string>{""});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, NewlineSplitter_BasicString) {
|
||||
TestNewlineSplitter("normal string", std::vector<std::string>{"normal string"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, NewlineSplitter_ormalBasicStringTrailingNewline) {
|
||||
TestNewlineSplitter("normal string\n", std::vector<std::string>{"normal string", ""});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, NewlineSplitter_MultilineTrailing) {
|
||||
TestNewlineSplitter("normal string\nsecond string\nthirdstring",
|
||||
std::vector<std::string>{"normal string", "second string", "thirdstring"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, NewlineSplitter_MultilineTrailingNewline) {
|
||||
TestNewlineSplitter(
|
||||
"normal string\nsecond string\nthirdstring\n",
|
||||
std::vector<std::string>{"normal string", "second string", "thirdstring", ""});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, NewlineSplitter_MultilineEmbeddedNewlines) {
|
||||
TestNewlineSplitter(
|
||||
"normal string\n\n\nsecond string\n\nthirdstring\n",
|
||||
std::vector<std::string>{"normal string", "", "", "second string", "", "thirdstring", ""});
|
||||
}
|
||||
|
||||
void TestLogdChunkSplitter(const std::string& tag, const std::string& file,
|
||||
const std::string& input,
|
||||
const std::vector<std::string>& expected_output) {
|
||||
std::vector<std::string> 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<std::string>{""});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, LogdChunkSplitter_BasicString) {
|
||||
TestLogdChunkSplitter("tag", "", "normal string", std::vector<std::string>{"normal string"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, LogdChunkSplitter_NormalBasicStringTrailingNewline) {
|
||||
TestLogdChunkSplitter("tag", "", "normal string\n", std::vector<std::string>{"normal string\n"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, LogdChunkSplitter_MultilineTrailing) {
|
||||
TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring",
|
||||
std::vector<std::string>{"normal string\nsecond string\nthirdstring"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, LogdChunkSplitter_MultilineTrailingNewline) {
|
||||
TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring\n",
|
||||
std::vector<std::string>{"normal string\nsecond string\nthirdstring\n"});
|
||||
}
|
||||
|
||||
TEST(logging_splitters, LogdChunkSplitter_MultilineEmbeddedNewlines) {
|
||||
TestLogdChunkSplitter(
|
||||
"tag", "", "normal string\n\n\nsecond string\n\nthirdstring\n",
|
||||
std::vector<std::string>{"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<int>(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
|
||||
|
|
@ -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 @@ 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
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in a new issue