tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Merge "liblog: retry -ENOTCONN | -ECONNREFUSED | -ENOENT indefinitely"

Browse source
This commit is contained in:
Treehugger Robot 2017-01-09 17:11:12 +00:00 committed by Gerrit Code Review
commit d5583867c6
2 changed files with 362 additions and 227 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

107
liblog/logd_writer.c
View file

@ -50,7 +50,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
LIBLOG_HIDDEN struct android_log_transport_write logdLoggerWrite = {
.node = { &logdLoggerWrite.node, &logdLoggerWrite.node },
.context.sock = -1,
.context.sock = -EBADF,
.name = "logd",
.available = logdAvailable,
.open = logdOpen,
@ -65,8 +65,10 @@ static int logdOpen()
i = atomic_load(&logdLoggerWrite.context.sock);
if (i < 0) {
i = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));
if (i < 0) {
int sock = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM |
SOCK_CLOEXEC |
SOCK_NONBLOCK, 0));
if (sock < 0) {
ret = -errno;
} else {
struct sockaddr_un un;
@ -74,13 +76,22 @@ static int logdOpen()
un.sun_family = AF_UNIX;
strcpy(un.sun_path, "/dev/socket/logdw");
if (TEMP_FAILURE_RETRY(connect(i, (struct sockaddr *)&un,
if (TEMP_FAILURE_RETRY(connect(sock, (struct sockaddr *)&un,
sizeof(struct sockaddr_un))) < 0) {
ret = -errno;
close(i);
switch (ret) {
case -ENOTCONN:
case -ECONNREFUSED:
case -ENOENT:
i = atomic_exchange(&logdLoggerWrite.context.sock, ret);
/* FALLTHRU */
default:
break;
}
close(sock);
} else {
ret = atomic_exchange(&logdLoggerWrite.context.sock, i);
if ((ret >= 0) && (ret != i)) {
ret = atomic_exchange(&logdLoggerWrite.context.sock, sock);
if ((ret >= 0) && (ret != sock)) {
close(ret);
}
ret = 0;
@ -91,14 +102,19 @@ static int logdOpen()
return ret;
}
static void logdClose()
static void __logdClose(int negative_errno)
{
int sock = atomic_exchange(&logdLoggerWrite.context.sock, -1);
int sock = atomic_exchange(&logdLoggerWrite.context.sock, negative_errno);
if (sock >= 0) {
close(sock);
}
}
static void logdClose()
{
__logdClose(-EBADF);
}
static int logdAvailable(log_id_t logId)
{
if (logId > LOG_ID_SECURITY) {
@ -117,6 +133,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
struct iovec *vec, size_t nr)
{
ssize_t ret;
int sock;
static const unsigned headerLength = 1;
struct iovec newVec[nr + headerLength];
android_log_header_t header;
@ -124,7 +141,13 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
static atomic_int_fast32_t dropped;
static atomic_int_fast32_t droppedSecurity;
if (atomic_load(&logdLoggerWrite.context.sock) < 0) {
sock = atomic_load(&logdLoggerWrite.context.sock);
if (sock < 0) switch (sock) {
case -ENOTCONN:
case -ECONNREFUSED:
case -ENOENT:
break;
default:
return -EBADF;
}
@ -163,7 +186,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
newVec[0].iov_base = (unsigned char *)&header;
newVec[0].iov_len = sizeof(header);
if (atomic_load(&logdLoggerWrite.context.sock) > 0) {
if (sock >= 0) {
int32_t snapshot = atomic_exchange_explicit(&droppedSecurity, 0,
memory_order_relaxed);
if (snapshot) {
@ -177,8 +200,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
newVec[headerLength].iov_base = &buffer;
newVec[headerLength].iov_len = sizeof(buffer);
ret = TEMP_FAILURE_RETRY(writev(
atomic_load(&logdLoggerWrite.context.sock), newVec, 2));
ret = TEMP_FAILURE_RETRY(writev(sock, newVec, 2));
if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) {
atomic_fetch_add_explicit(&droppedSecurity, snapshot,
memory_order_relaxed);
@ -186,7 +208,8 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
}
snapshot = atomic_exchange_explicit(&dropped, 0, memory_order_relaxed);
if (snapshot && __android_log_is_loggable_len(ANDROID_LOG_INFO,
"liblog", strlen("liblog"),
"liblog",
strlen("liblog"),
ANDROID_LOG_VERBOSE)) {
android_log_event_int_t buffer;
@ -198,8 +221,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
newVec[headerLength].iov_base = &buffer;
newVec[headerLength].iov_len = sizeof(buffer);
ret = TEMP_FAILURE_RETRY(writev(
atomic_load(&logdLoggerWrite.context.sock), newVec, 2));
ret = TEMP_FAILURE_RETRY(writev(sock, newVec, 2));
if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) {
atomic_fetch_add_explicit(&dropped, snapshot,
memory_order_relaxed);
@ -225,30 +247,43 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
/*
* The write below could be lost, but will never block.
*
* ENOTCONN occurs if logd dies.
* ENOTCONN occurs if logd has died.
* ENOENT occurs if logd is not running and socket is missing.
* ECONNREFUSED occurs if we can not reconnect to logd.
* EAGAIN occurs if logd is overloaded.
*/
ret = TEMP_FAILURE_RETRY(writev(
atomic_load(&logdLoggerWrite.context.sock), newVec, i));
if (ret < 0) {
ret = -errno;
if (ret == -ENOTCONN) {
__android_log_lock();
logdClose();
ret = logdOpen();
__android_log_unlock();
if (ret < 0) {
return ret;
}
ret = TEMP_FAILURE_RETRY(writev(
atomic_load(&logdLoggerWrite.context.sock), newVec, i));
if (ret < 0) {
ret = -errno;
}
if (sock < 0) {
ret = sock;
} else {
ret = TEMP_FAILURE_RETRY(writev(sock, newVec, i));
if (ret < 0) {
ret = -errno;
}
}
switch(ret) {
case -ENOTCONN:
case -ECONNREFUSED:
case -ENOENT:
if (__android_log_trylock()) {
return ret; /* in a signal handler? try again when less stressed */
}
__logdClose(ret);
ret = logdOpen();
__android_log_unlock();
if (ret < 0) {
return ret;
}
ret = TEMP_FAILURE_RETRY(writev(
atomic_load(&logdLoggerWrite.context.sock), newVec, i));
if (ret < 0) {
ret = -errno;
}
/* FALLTHRU */
default:
break;
}
if (ret > (ssize_t)sizeof(header)) {
ret -= sizeof(header);

482
liblog/tests/liblog_test.cpp
View file

@ -504,190 +504,6 @@ TEST(liblog, __android_log_buf_write_and_print__newline_space_prefix) {
buf_write_test("\n Hello World \n");
}
TEST(liblog, __security) {
#ifdef __ANDROID__
static const char persist_key[] = "persist.logd.security";
static const char readonly_key[] = "ro.device_owner";
static const char nothing_val[] = "_NOTHING_TO_SEE_HERE_";
char persist[PROP_VALUE_MAX];
char readonly[PROP_VALUE_MAX];
property_get(persist_key, persist, "");
property_get(readonly_key, readonly, nothing_val);
if (!strcmp(readonly, nothing_val)) {
EXPECT_FALSE(__android_log_security());
fprintf(stderr, "Warning, setting ro.device_owner to a domain\n");
property_set(readonly_key, "com.google.android.SecOps.DeviceOwner");
} else if (!strcasecmp(readonly, "false") || !readonly[0]) {
EXPECT_FALSE(__android_log_security());
return;
}
if (!strcasecmp(persist, "true")) {
EXPECT_TRUE(__android_log_security());
} else {
EXPECT_FALSE(__android_log_security());
}
property_set(persist_key, "TRUE");
EXPECT_TRUE(__android_log_security());
property_set(persist_key, "FALSE");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, "true");
EXPECT_TRUE(__android_log_security());
property_set(persist_key, "false");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, "");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, persist);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
TEST(liblog, __security_buffer) {
#ifdef __ANDROID__
struct logger_list *logger_list;
android_event_long_t buffer;
static const char persist_key[] = "persist.logd.security";
char persist[PROP_VALUE_MAX];
bool set_persist = false;
bool allow_security = false;
if (__android_log_security()) {
allow_security = true;
} else {
property_get(persist_key, persist, "");
if (strcasecmp(persist, "true")) {
property_set(persist_key, "TRUE");
if (__android_log_security()) {
allow_security = true;
set_persist = true;
} else {
property_set(persist_key, persist);
}
}
}
if (!allow_security) {
fprintf(stderr, "WARNING: "
"security buffer disabled, bypassing end-to-end test\n");
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
// expect failure!
ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
return;
}
/* Matches clientHasLogCredentials() in logd */
uid_t uid = getuid();
gid_t gid = getgid();
bool clientHasLogCredentials = true;
if ((uid != AID_SYSTEM) && (uid != AID_ROOT) && (uid != AID_LOG)
&& (gid != AID_SYSTEM) && (gid != AID_ROOT) && (gid != AID_LOG)) {
uid_t euid = geteuid();
if ((euid != AID_SYSTEM) && (euid != AID_ROOT) && (euid != AID_LOG)) {
gid_t egid = getegid();
if ((egid != AID_SYSTEM) && (egid != AID_ROOT) && (egid != AID_LOG)) {
int num_groups = getgroups(0, NULL);
if (num_groups > 0) {
gid_t groups[num_groups];
num_groups = getgroups(num_groups, groups);
while (num_groups > 0) {
if (groups[num_groups - 1] == AID_LOG) {
break;
}
--num_groups;
}
}
if (num_groups <= 0) {
clientHasLogCredentials = false;
}
}
}
}
if (!clientHasLogCredentials) {
fprintf(stderr, "WARNING: "
"not in system context, bypassing end-to-end test\n");
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
// expect failure!
ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
return;
}
setuid(AID_SYSTEM); // only one that can read security buffer
pid_t pid = getpid();
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_SECURITY, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
1000, pid)));
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
ASSERT_LT(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != sizeof(android_log_event_long_t))
|| (log_msg.id() != LOG_ID_SECURITY)) {
continue;
}
android_log_event_long_t* eventData;
eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
if (ts == tx) {
++count;
}
}
if (set_persist) {
property_set(persist_key, persist);
}
android_logger_list_close(logger_list);
bool clientHasSecurityCredentials = (uid == AID_SYSTEM) || (gid == AID_SYSTEM);
if (!clientHasSecurityCredentials) {
fprintf(stderr, "WARNING: "
"not system, content submitted but can not check end-to-end\n");
}
EXPECT_EQ(clientHasSecurityCredentials ? 1 : 0, count);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
#ifdef __ANDROID__
static unsigned signaled;
static log_time signal_time;
@ -1375,6 +1191,9 @@ TEST(liblog, dual_reader) {
TEST(liblog, android_logger_get_) {
#ifdef __ANDROID__
// This test assumes the log buffers are filled with noise from
// normal operations. It will fail if done immediately after a
// logcat -c.
struct logger_list * logger_list = android_logger_list_alloc(ANDROID_LOG_WRONLY, 0, 0);
for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) {
@ -1785,6 +1604,294 @@ TEST(liblog, is_loggable) {
#endif
}
#ifdef __ANDROID__
// helper to liblog.enoent to count end-to-end matching logging messages.
static int count_matching_ts(log_time ts) {
usleep(1000000);
pid_t pid = getpid();
struct logger_list* logger_list = android_logger_list_open(
LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid);
int count = 0;
if (logger_list == NULL) return count;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
if (log_msg.entry.len != sizeof(android_log_event_long_t)) continue;
if (log_msg.id() != LOG_ID_EVENTS) continue;
android_log_event_long_t* eventData;
eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
if (!eventData) continue;
if (eventData->payload.type != EVENT_TYPE_LONG) continue;
log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
if (ts != tx) continue;
// found event message with matching timestamp signature in payload
++count;
}
android_logger_list_close(logger_list);
return count;
}
// meant to be handed to ASSERT_TRUE / EXPECT_TRUE only to expand the message
static testing::AssertionResult IsOk(bool ok, std::string &message) {
return ok ?
testing::AssertionSuccess() :
(testing::AssertionFailure() << message);
}
#endif
TEST(liblog, enoent) {
#ifdef __ANDROID__
log_time ts(CLOCK_MONOTONIC);
EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
EXPECT_EQ(1, count_matching_ts(ts));
// This call will fail if we are setuid(AID_SYSTEM), beware of any
// test prior to this one playing with setuid and causing interference.
// We need to run before these tests so that they do not interfere with
// this test.
//
// Stopping the logger can affect some other test's expectations as they
// count on the log buffers filled with existing content, and this
// effectively does a logcat -c emptying it. So we want this test to be
// as near as possible to the bottom of the file. For example
// liblog.android_logger_get_ is one of those tests that has no recourse
// and that would be adversely affected by emptying the log if it was run
// right after this test.
system("stop logd");
usleep(1000000);
// A clean stop like we are testing returns -ENOENT, but in the _real_
// world we could get -ENOTCONN or -ECONNREFUSED depending on timing.
// Alas we can not test these other return values; accept that they
// are treated equally within the open-retry logic in liblog.
ts = log_time(CLOCK_MONOTONIC);
int ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
std::string content = android::base::StringPrintf(
"__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
ret, strerror(-ret));
EXPECT_TRUE(IsOk((ret == -ENOENT) ||
(ret == -ENOTCONN) ||
(ret == -ECONNREFUSED), content));
ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
content = android::base::StringPrintf(
"__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
ret, strerror(-ret));
EXPECT_TRUE(IsOk((ret == -ENOENT) ||
(ret == -ENOTCONN) ||
(ret == -ECONNREFUSED), content));
EXPECT_EQ(0, count_matching_ts(ts));
system("start logd");
usleep(1000000);
EXPECT_EQ(0, count_matching_ts(ts));
ts = log_time(CLOCK_MONOTONIC);
EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
EXPECT_EQ(1, count_matching_ts(ts));
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
// Below this point we run risks of setuid(AID_SYSTEM) which may affect others.
TEST(liblog, __security) {
#ifdef __ANDROID__
static const char persist_key[] = "persist.logd.security";
static const char readonly_key[] = "ro.device_owner";
// A silly default value that can never be in readonly_key so
// that it can be determined the property is not set.
static const char nothing_val[] = "_NOTHING_TO_SEE_HERE_";
char persist[PROP_VALUE_MAX];
char readonly[PROP_VALUE_MAX];
property_get(persist_key, persist, "");
property_get(readonly_key, readonly, nothing_val);
if (!strcmp(readonly, nothing_val)) {
EXPECT_FALSE(__android_log_security());
fprintf(stderr, "Warning, setting ro.device_owner to a domain\n");
property_set(readonly_key, "com.google.android.SecOps.DeviceOwner");
} else if (!strcasecmp(readonly, "false") || !readonly[0]) {
EXPECT_FALSE(__android_log_security());
return;
}
if (!strcasecmp(persist, "true")) {
EXPECT_TRUE(__android_log_security());
} else {
EXPECT_FALSE(__android_log_security());
}
property_set(persist_key, "TRUE");
EXPECT_TRUE(__android_log_security());
property_set(persist_key, "FALSE");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, "true");
EXPECT_TRUE(__android_log_security());
property_set(persist_key, "false");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, "");
EXPECT_FALSE(__android_log_security());
property_set(persist_key, persist);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
TEST(liblog, __security_buffer) {
#ifdef __ANDROID__
struct logger_list *logger_list;
android_event_long_t buffer;
static const char persist_key[] = "persist.logd.security";
char persist[PROP_VALUE_MAX];
bool set_persist = false;
bool allow_security = false;
if (__android_log_security()) {
allow_security = true;
} else {
property_get(persist_key, persist, "");
if (strcasecmp(persist, "true")) {
property_set(persist_key, "TRUE");
if (__android_log_security()) {
allow_security = true;
set_persist = true;
} else {
property_set(persist_key, persist);
}
}
}
if (!allow_security) {
fprintf(stderr, "WARNING: "
"security buffer disabled, bypassing end-to-end test\n");
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
// expect failure!
ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
return;
}
/* Matches clientHasLogCredentials() in logd */
uid_t uid = getuid();
gid_t gid = getgid();
bool clientHasLogCredentials = true;
if ((uid != AID_SYSTEM) && (uid != AID_ROOT) && (uid != AID_LOG)
&& (gid != AID_SYSTEM) && (gid != AID_ROOT) && (gid != AID_LOG)) {
uid_t euid = geteuid();
if ((euid != AID_SYSTEM) && (euid != AID_ROOT) && (euid != AID_LOG)) {
gid_t egid = getegid();
if ((egid != AID_SYSTEM) && (egid != AID_ROOT) && (egid != AID_LOG)) {
int num_groups = getgroups(0, NULL);
if (num_groups > 0) {
gid_t groups[num_groups];
num_groups = getgroups(num_groups, groups);
while (num_groups > 0) {
if (groups[num_groups - 1] == AID_LOG) {
break;
}
--num_groups;
}
}
if (num_groups <= 0) {
clientHasLogCredentials = false;
}
}
}
}
if (!clientHasLogCredentials) {
fprintf(stderr, "WARNING: "
"not in system context, bypassing end-to-end test\n");
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
// expect failure!
ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
return;
}
setuid(AID_SYSTEM); // only one that can read security buffer
pid_t pid = getpid();
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_SECURITY, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
1000, pid)));
log_time ts(CLOCK_MONOTONIC);
buffer.type = EVENT_TYPE_LONG;
buffer.data = *(static_cast<uint64_t *>((void *)&ts));
ASSERT_LT(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != sizeof(android_log_event_long_t))
|| (log_msg.id() != LOG_ID_SECURITY)) {
continue;
}
android_log_event_long_t* eventData;
eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
if (ts == tx) {
++count;
}
}
if (set_persist) {
property_set(persist_key, persist);
}
android_logger_list_close(logger_list);
bool clientHasSecurityCredentials = (uid == AID_SYSTEM) || (gid == AID_SYSTEM);
if (!clientHasSecurityCredentials) {
fprintf(stderr, "WARNING: "
"not system, content submitted but can not check end-to-end\n");
}
EXPECT_EQ(clientHasSecurityCredentials ? 1 : 0, count);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
#ifdef __ANDROID__
static void android_errorWriteWithInfoLog_helper(int TAG, const char* SUBTAG,
int UID, const char* payload,
@ -2803,13 +2910,6 @@ TEST(liblog, __android_log_pmsg_file_read) {
}
#ifdef __ANDROID__
// meant to be handed to ASSERT_TRUE / EXPECT_TRUE only to expand the message
static testing::AssertionResult IsOk(bool ok, std::string &message) {
return ok ?
testing::AssertionSuccess() :
(testing::AssertionFailure() << message);
}
// must be: '<needle:> 0 kB'
static bool isZero(const std::string &content, std::string::size_type pos,
const char* needle) {