libbase output in host now look similar to the logcat output on device
I8189501d123fb79a255e17f675f8f6be617022e8 changed the output format of
host-side liblog. This change does the same for libbase.
For some unknown reason I don't fully understand, libbase has formatted
host-side logs by itself without relying on liblog. (note that libbase
"always" depends on liblog even for hosts. A follow-up might be reduce
the code duplication across libbase and liblog.
Bug: 287910948
Test: see the host logs
Test: atest --host libbase_test:logging_splitters
Test: atest --host libbase_test:logging
Test: atest --host libblog-host-test
Change-Id: Ie220d78a1c15686be7ae34cd5be88b858903f2e1
diff --git a/logging.cpp b/logging.cpp
index e6c02ba..b296d3b 100644
--- a/logging.cpp
+++ b/logging.cpp
@@ -277,16 +277,10 @@
void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file, unsigned int line,
const char* message) {
- struct tm now;
- time_t t = time(nullptr);
-
-#if defined(_WIN32)
- localtime_s(&now, &t);
-#else
- localtime_r(&t, &now);
-#endif
+ struct timespec ts;
+ clock_gettime(CLOCK_REALTIME, &ts);
auto output_string =
- StderrOutputGenerator(now, getpid(), GetThreadId(), severity, tag, file, line, message);
+ StderrOutputGenerator(ts, getpid(), GetThreadId(), severity, tag, file, line, message);
fputs(output_string.c_str(), stderr);
}
diff --git a/logging_splitters.h b/logging_splitters.h
index 2ec2b20..896ffc8 100644
--- a/logging_splitters.h
+++ b/logging_splitters.h
@@ -145,23 +145,31 @@
// 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,
+static std::string StderrOutputGenerator(const struct timespec& ts, 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);
+ struct tm now;
+#if defined(_WIN32)
+ localtime_s(&now, &ts.tv_sec);
+#else
+ localtime_r(&ts.tv_sec, &now);
+#endif
+ char timestamp[sizeof("mm-DD HH:MM:SS.mmm\0")];
+ size_t n = strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now);
+ snprintf(timestamp + n, sizeof(timestamp) - n, ".%03ld", ts.tv_nsec / (1000 * 1000));
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;
+ const char* real_tag = tag ? tag : "nullptr";
if (file != nullptr) {
- line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " %s:%u] ", tag ? tag : "nullptr",
- severity_char, timestamp, pid, tid, file, line);
+ line_prefix = StringPrintf("%s %5d %5" PRIu64 " %c %-8s: %s:%u ", timestamp, pid, tid,
+ severity_char, real_tag, file, line);
} else {
- line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " ", tag ? tag : "nullptr", severity_char,
- timestamp, pid, tid);
+ line_prefix =
+ StringPrintf("%s %5d %5" PRIu64 " %c %-8s: ", timestamp, pid, tid, severity_char, real_tag);
}
auto [size, new_lines] = CountSizeAndNewLines(message);
diff --git a/logging_splitters_test.cpp b/logging_splitters_test.cpp
index 679d19e..7b4e6b5 100644
--- a/logging_splitters_test.cpp
+++ b/logging_splitters_test.cpp
@@ -253,58 +253,51 @@
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,
- };
+ // All log messages will show "01-01 00:00:00.000"
+ struct timespec ts = {.tv_sec = 0, .tv_nsec = 0};
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);
+ auto result = StderrOutputGenerator(ts, 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");
+ "01-01 00:00:00.000 1234 4321 E nullptr : simple message\n");
TestStderrOutputGenerator("tag", nullptr, 0, "simple message",
- "tag E 01-01 00:00:00 1234 4321 simple message\n");
+ "01-01 00:00:00.000 1234 4321 E tag : 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");
+ "01-01 00:00:00.000 1234 4321 E tag : /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");
+ "01-01 00:00:00.000 1234 4321 E tag\n\n : 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");
+ "01-01 00:00:00.000 1234 4321 E tag : /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");
+ TestStderrOutputGenerator("tag", nullptr, 0, "simple message\n",
+ "01-01 00:00:00.000 1234 4321 E tag : simple message\n"
+ "01-01 00:00:00.000 1234 4321 E tag : \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";
+ "01-01 00:00:00.000 1234 4321 E tag : simple message\n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n"
+ "01-01 00:00:00.000 1234 4321 E tag : another message \n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n"
+ "01-01 00:00:00.000 1234 4321 E tag : final message \n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n"
+ "01-01 00:00:00.000 1234 4321 E tag : \n";
TestStderrOutputGenerator("tag", nullptr, 0,
"simple message\n\n\nanother message \n\n final message \n\n\n",
@@ -316,8 +309,8 @@
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';
+ auto expected_result = "01-01 00:00:00.000 1234 4321 E tag : " + long_string_a + '\n' +
+ "01-01 00:00:00.000 1234 4321 E tag : " + long_string_b + '\n';
TestStderrOutputGenerator("tag", nullptr, 0, message.c_str(), expected_result);
}
diff --git a/logging_test.cpp b/logging_test.cpp
index be2e042..c3705ea 100644
--- a/logging_test.cpp
+++ b/logging_test.cpp
@@ -209,16 +209,24 @@
#if !defined(_WIN32)
-static std::string make_log_pattern(android::base::LogSeverity severity,
+static std::string make_log_pattern(const char* expected_tag, android::base::LogSeverity severity,
const char* message) {
static const char log_characters[] = "VDIWEFF";
static_assert(arraysize(log_characters) - 1 == android::base::FATAL + 1,
"Mismatch in size of log_characters and values in LogSeverity");
char log_char = log_characters[severity];
std::string holder(__FILE__);
+
+ // `message` can have a function name like "TestBody()". The parentheses should be escaped,
+ // otherwise it will be interpreted as a capturing group when it is used as a regex. Below
+ // replaces either '(' or ')' to '\(' or '\)', respectively.
+ std::regex parentheses(R"(\(|\))");
+ std::string message_escaped = std::regex_replace(message, parentheses, R"(\$&)");
+
+ const char* tag_pattern = expected_tag != nullptr ? expected_tag : ".+";
return android::base::StringPrintf(
- "%c \\d+-\\d+ \\d+:\\d+:\\d+ \\s*\\d+ \\s*\\d+ %s:\\d+] %s",
- log_char, basename(&holder[0]), message);
+ R"(\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} \s*\d+ \s*\d+ %c %s\s*: %s:\d+ %s)", log_char,
+ tag_pattern, basename(&holder[0]), message_escaped.c_str());
}
#endif
@@ -234,12 +242,7 @@
}
#if !defined(_WIN32)
- std::string regex_str;
- if (expected_tag != nullptr) {
- regex_str.append(expected_tag);
- regex_str.append(" ");
- }
- regex_str.append(make_log_pattern(severity, expected));
+ std::string regex_str = make_log_pattern(expected_tag, severity, expected);
std::regex message_regex(regex_str);
ASSERT_TRUE(std::regex_search(output, message_regex)) << output;
#endif