Merge "base: reimagine line splitting in logger.cpp" into rvc-dev
This commit is contained in:
Tom Cherry
Android (Google) Code Review
commit
806c0206b8
6 changed files with 597 additions and 64 deletions
|
|
@ -159,6 +159,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