liblog: fix host tests

1) Fix up the host tests for new logging format
2) Add recently added tests to the host test
3) Ensure that properties are cleaned up by liblog-unit-tests

Test: unit tests
Change-Id: I303549aecc26d11ec87e59d48758ced4c198b72c
This commit is contained in:
Tom Cherry 2020-01-27 16:20:35 -08:00
parent f48f685e60
commit 5676f3d916
4 changed files with 108 additions and 107 deletions

View file

@ -104,6 +104,11 @@ cc_test_host {
name: "liblog-host-test",
static_libs: ["liblog"],
shared_libs: ["libbase"],
srcs: ["liblog_host_test.cpp"],
srcs: [
"liblog_host_test.cpp",
"liblog_default_tag.cpp",
"liblog_global_state.cpp",
"rwlock_test.cpp",
],
isolated: true,
}

View file

@ -22,10 +22,17 @@
#include <android-base/file.h>
#include <android-base/logging.h>
#include <android-base/properties.h>
#include <android-base/scopeguard.h>
#include <android/log.h>
#include <gtest/gtest.h>
#ifndef __ANDROID__
static const char* getprogname() {
return program_invocation_short_name;
}
#endif
TEST(liblog_default_tag, no_default_tag_libbase_write_first) {
using namespace android::base;
bool message_seen = false;
@ -99,6 +106,7 @@ TEST(liblog_default_tag, liblog_sets_default_tag) {
}
TEST(liblog_default_tag, default_tag_plus_log_severity) {
#ifdef __ANDROID__
using namespace android::base;
bool message_seen = false;
std::string expected_tag = "liblog_test_tag";
@ -110,6 +118,7 @@ TEST(liblog_default_tag, default_tag_plus_log_severity) {
auto log_tag_property = "log.tag." + expected_tag;
SetProperty(log_tag_property, "V");
auto reset_tag_property_guard = make_scope_guard([=] { SetProperty(log_tag_property, ""); });
__android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_VERBOSE, nullptr, "message");
EXPECT_TRUE(message_seen);
@ -117,9 +126,13 @@ TEST(liblog_default_tag, default_tag_plus_log_severity) {
LOG(VERBOSE) << "message";
EXPECT_TRUE(message_seen);
#else
GTEST_SKIP() << "No log tag properties on host";
#endif
}
TEST(liblog_default_tag, generated_default_tag_plus_log_severity) {
#ifdef __ANDROID__
using namespace android::base;
bool message_seen = false;
std::string expected_tag = getprogname();
@ -133,6 +146,7 @@ TEST(liblog_default_tag, generated_default_tag_plus_log_severity) {
// case checks that we can log a Verbose message when log.tag.<getprogname()> is set to 'V'.
auto log_tag_property = "log.tag." + expected_tag;
SetProperty(log_tag_property, "V");
auto reset_tag_property_guard = make_scope_guard([=] { SetProperty(log_tag_property, ""); });
__android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_VERBOSE, nullptr, "message");
EXPECT_TRUE(message_seen);
@ -140,4 +154,7 @@ TEST(liblog_default_tag, generated_default_tag_plus_log_severity) {
LOG(VERBOSE) << "message";
EXPECT_TRUE(message_seen);
#else
GTEST_SKIP() << "No log tag properties on host";
#endif
}

View file

@ -188,6 +188,7 @@ TEST(liblog_global_state, is_loggable_minimum_log_priority_only) {
}
TEST(liblog_global_state, is_loggable_tag_log_priority_only) {
#ifdef __ANDROID__
EXPECT_EQ(0, __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG, ANDROID_LOG_INFO));
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_INFO, LOG_TAG, ANDROID_LOG_INFO));
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_WARN, LOG_TAG, ANDROID_LOG_INFO));
@ -204,9 +205,13 @@ TEST(liblog_global_state, is_loggable_tag_log_priority_only) {
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_WARN, LOG_TAG, ANDROID_LOG_INFO));
android::base::SetProperty(log_tag_property, "");
#else
GTEST_SKIP() << "No log tag properties on host";
#endif
}
TEST(liblog_global_state, is_loggable_both_set) {
#ifdef __ANDROID__
EXPECT_EQ(0, __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG, ANDROID_LOG_INFO));
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_INFO, LOG_TAG, ANDROID_LOG_INFO));
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_WARN, LOG_TAG, ANDROID_LOG_INFO));
@ -240,4 +245,7 @@ TEST(liblog_global_state, is_loggable_both_set) {
EXPECT_EQ(1, __android_log_is_loggable(ANDROID_LOG_WARN, LOG_TAG, ANDROID_LOG_INFO));
android::base::SetProperty(log_tag_property, "");
#else
GTEST_SKIP() << "No log tag properties on host";
#endif
}

View file

@ -20,15 +20,37 @@
#include <stdlib.h>
#include <unistd.h>
#include <regex>
#include <string>
#include <android-base/logging.h>
#include <android-base/macros.h>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <android-base/test_utils.h>
#include <gtest/gtest.h>
using android::base::InitLogging;
using android::base::StderrLogger;
using android::base::StringPrintf;
using android::base::StringReplace;
void GenerateLogContent() {
static std::string MakeLogPattern(int priority, const char* tag, const char* message) {
static const char log_characters[] = "XXVDIWEF";
static_assert(arraysize(log_characters) - 1 == ANDROID_LOG_SILENT,
"Mismatch in size of log_characters and values in android_LogPriority");
priority = priority > ANDROID_LOG_SILENT ? ANDROID_LOG_FATAL : priority;
char log_char = log_characters[priority];
return StringPrintf("%s %c \\d+-\\d+ \\d+:\\d+:\\d+ \\s*\\d+ \\s*\\d+ %s", tag, log_char,
message);
}
static void CheckMessage(bool expected, const std::string& output, int priority, const char* tag,
const char* message) {
std::regex message_regex(MakeLogPattern(priority, tag, message));
EXPECT_EQ(expected, std::regex_search(output, message_regex)) << message;
}
static void GenerateLogContent() {
__android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_VERBOSE, "tag", "verbose main");
__android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, "tag", "info main");
__android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_ERROR, "tag", "error main");
@ -52,137 +74,86 @@ std::string GetPidString() {
}
TEST(liblog, default_write) {
setenv("ANDROID_PRINTF_LOG", "brief", true);
CapturedStderr captured_stderr;
InitLogging(nullptr, StderrLogger);
GenerateLogContent();
std::string expected_output = StringReplace(R"init(I/tag (<pid>): info main
E/tag (<pid>): error main
I/tag (<pid>): info radio
E/tag (<pid>): error radio
I/tag (<pid>): info system
E/tag (<pid>): error system
I/tag (<pid>): info crash
E/tag (<pid>): error crash
)init",
"<pid>", GetPidString(), true);
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose main");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info main");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error main");
EXPECT_EQ(expected_output, captured_stderr.str());
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose radio");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info radio");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error radio");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose system");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info system");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error system");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose crash");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info crash");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error crash");
}
TEST(liblog, format) {
setenv("ANDROID_PRINTF_LOG", "process", true);
TEST(liblog, verbose_write) {
setenv("ANDROID_LOG_TAGS", "*:v", true);
CapturedStderr captured_stderr;
InitLogging(nullptr, StderrLogger);
GenerateLogContent();
std::string expected_output = StringReplace(R"init(I(<pid>) info main (tag)
E(<pid>) error main (tag)
I(<pid>) info radio (tag)
E(<pid>) error radio (tag)
I(<pid>) info system (tag)
E(<pid>) error system (tag)
I(<pid>) info crash (tag)
E(<pid>) error crash (tag)
)init",
"<pid>", GetPidString(), true);
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose main");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info main");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error main");
EXPECT_EQ(expected_output, captured_stderr.str());
captured_stderr.Stop();
captured_stderr.Reset();
captured_stderr.Start();
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose radio");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info radio");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error radio");
// Changing the environment after starting writing doesn't change the format.
setenv("ANDROID_PRINTF_LOG", "brief", true);
GenerateLogContent();
EXPECT_EQ(expected_output, captured_stderr.str());
captured_stderr.Stop();
captured_stderr.Reset();
captured_stderr.Start();
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose system");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info system");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error system");
// However calling __android_log_close() does reset logging and allow changing the format.
__android_log_close();
GenerateLogContent();
expected_output = StringReplace(R"init(I/tag (<pid>): info main
E/tag (<pid>): error main
I/tag (<pid>): info radio
E/tag (<pid>): error radio
I/tag (<pid>): info system
E/tag (<pid>): error system
I/tag (<pid>): info crash
E/tag (<pid>): error crash
)init",
"<pid>", GetPidString(), true);
EXPECT_EQ(expected_output, captured_stderr.str());
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose crash");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info crash");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error crash");
}
TEST(liblog, filter) {
setenv("ANDROID_PRINTF_LOG", "brief", true);
setenv("ANDROID_LOG_TAGS", "*:w verbose_tag:v debug_tag:d", true);
CapturedStderr captured_stderr;
auto generate_logs = [](log_id_t log_id) {
// Check that we show verbose logs when requesting for a given tag.
__android_log_buf_print(log_id, ANDROID_LOG_VERBOSE, "verbose_tag", "verbose verbose_tag");
__android_log_buf_print(log_id, ANDROID_LOG_ERROR, "verbose_tag", "error verbose_tag");
// Check that we don't show verbose logs when explicitly requesting debug+ for a given tag.
__android_log_buf_print(log_id, ANDROID_LOG_VERBOSE, "debug_tag", "verbose debug_tag");
__android_log_buf_print(log_id, ANDROID_LOG_DEBUG, "debug_tag", "debug debug_tag");
__android_log_buf_print(log_id, ANDROID_LOG_ERROR, "debug_tag", "error debug_tag");
// Check that we don't show info logs when requesting globally warn+.
__android_log_buf_print(log_id, ANDROID_LOG_INFO, "default_tag", "info default_tag");
__android_log_buf_print(log_id, ANDROID_LOG_WARN, "default_tag", "warn default_tag");
__android_log_buf_print(log_id, ANDROID_LOG_ERROR, "default_tag", "error default_tag");
};
auto expected_output = StringReplace(R"init(V/verbose_tag(<pid>): verbose verbose_tag
E/verbose_tag(<pid>): error verbose_tag
D/debug_tag(<pid>): debug debug_tag
E/debug_tag(<pid>): error debug_tag
W/default_tag(<pid>): warn default_tag
E/default_tag(<pid>): error default_tag
)init",
"<pid>", GetPidString(), true);
auto test_all_logs = [&] {
for (auto log_id : {LOG_ID_MAIN, LOG_ID_SYSTEM, LOG_ID_RADIO, LOG_ID_CRASH}) {
generate_logs(log_id);
EXPECT_EQ(expected_output, captured_stderr.str());
captured_stderr.Stop();
captured_stderr.Reset();
captured_stderr.Start();
}
};
test_all_logs();
// Changing the environment after starting writing doesn't change the filter.
TEST(liblog, error_write) {
setenv("ANDROID_LOG_TAGS", "*:e", true);
test_all_logs();
CapturedStderr captured_stderr;
InitLogging(nullptr, StderrLogger);
// However calling __android_log_close() does reset logging and allow changing the format.
__android_log_close();
expected_output = StringReplace(R"init(E/verbose_tag(<pid>): error verbose_tag
E/debug_tag(<pid>): error debug_tag
E/default_tag(<pid>): error default_tag
)init",
"<pid>", GetPidString(), true);
test_all_logs();
GenerateLogContent();
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose main");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info main");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error main");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose radio");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info radio");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error radio");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose system");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info system");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error system");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_VERBOSE, "tag", "verbose crash");
CheckMessage(false, captured_stderr.str(), ANDROID_LOG_INFO, "tag", "info crash");
CheckMessage(true, captured_stderr.str(), ANDROID_LOG_ERROR, "tag", "error crash");
}
TEST(liblog, kernel_no_write) {
CapturedStderr captured_stderr;
InitLogging(nullptr, StderrLogger);
__android_log_buf_print(LOG_ID_KERNEL, ANDROID_LOG_ERROR, "tag", "kernel error");
EXPECT_EQ("", captured_stderr.str());
}
TEST(liblog, binary_no_write) {
CapturedStderr captured_stderr;
InitLogging(nullptr, StderrLogger);
__android_log_buf_print(LOG_ID_EVENTS, ANDROID_LOG_ERROR, "tag", "error events");
__android_log_buf_print(LOG_ID_STATS, ANDROID_LOG_ERROR, "tag", "error stats");
__android_log_buf_print(LOG_ID_SECURITY, ANDROID_LOG_ERROR, "tag", "error security");