liblog: resolve deadlocks
Although ever present, an increased regression introduced with
commit b6bee33182cedea49199eb2252b3f3b442899c6d (liblog: logd:
support logd.timestamp = monotonic).
A signal handler can interrupt in locked context, if log is written
in the signal handler, we are in deadlock. Block signals while we
are locked. Separate out timestamp lock from is loggable lock to
reduce contention situations. Provide a best-guess response if
lock would fail in timestamp path.
Bug: 25563384
Change-Id: I6dccd6b99ebace1c473c03a785a35c63ed5c6a8a
diff --git a/include/log/log.h b/include/log/log.h
index 1cdf7bc..e0dc3a3 100644
--- a/include/log/log.h
+++ b/include/log/log.h
@@ -616,7 +616,12 @@
* Use the per-tag properties "log.tag.<tagname>" to generate a runtime
* result of non-zero to expose a log.
*/
-int __android_log_is_loggable(int prio, const char *tag, int def);
+/* default prio ANDROID_LOG_VERBOSE to ANDROID_LOG_FATAL if no property */
+#define ANDROID_LOGGABLE_FLAG_DEFAULT_MASK 0x000F
+/* Save 2 syscalls if caller guarantees to never call within signal handler */
+#define ANDROID_LOGGABLE_FLAG_NOT_WITHIN_SIGNAL 0x8000
+
+int __android_log_is_loggable(int prio, const char *tag, int flag);
int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data,
uint32_t dataLen);
diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c
index 8a8ece2..fcdb6c9 100644
--- a/liblog/fake_log_device.c
+++ b/liblog/fake_log_device.c
@@ -24,6 +24,7 @@
#include <ctype.h>
#include <errno.h>
#include <fcntl.h>
+#include <signal.h>
#include <stdlib.h>
#include <string.h>
@@ -97,18 +98,33 @@
*/
static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER;
-static void lock()
+static void lock(sigset_t *sigflags)
{
+ /*
+ * If we trigger a signal handler in the middle of locked activity and the
+ * signal handler logs a message, we could get into a deadlock state.
+ */
+ sigset_t all;
+
+ sigfillset(&all);
+ pthread_sigmask(SIG_BLOCK, &all, sigflags);
pthread_mutex_lock(&fakeLogDeviceLock);
}
-static void unlock()
+static void unlock(sigset_t *sigflags)
{
pthread_mutex_unlock(&fakeLogDeviceLock);
+ pthread_sigmask(SIG_UNBLOCK, sigflags, NULL);
}
+
+#define DECLARE_SIGSET(name) sigset_t name
+
#else // !defined(_WIN32)
-#define lock() ((void)0)
-#define unlock() ((void)0)
+
+#define lock(sigflags) ((void)0)
+#define unlock(sigflags) ((void)0)
+#define DECLARE_SIGSET(name)
+
#endif // !defined(_WIN32)
@@ -154,8 +170,9 @@
static void deleteFakeFd(int fd)
{
LogState *ls;
+ DECLARE_SIGSET(sigflags);
- lock();
+ lock(&sigflags);
ls = fdToLogState(fd);
if (ls != NULL) {
@@ -164,7 +181,7 @@
free(ls);
}
- unlock();
+ unlock(&sigflags);
}
/*
@@ -548,12 +565,13 @@
static ssize_t logWritev(int fd, const struct iovec* vector, int count)
{
LogState* state;
+ DECLARE_SIGSET(sigflags);
/* Make sure that no-one frees the LogState while we're using it.
* Also guarantees that only one thread is in showLog() at a given
* time (if it matters).
*/
- lock();
+ lock(&sigflags);
state = fdToLogState(fd);
if (state == NULL) {
@@ -598,10 +616,10 @@
}
bail:
- unlock();
+ unlock(&sigflags);
return vector[0].iov_len + vector[1].iov_len + vector[2].iov_len;
error:
- unlock();
+ unlock(&sigflags);
return -1;
}
@@ -621,8 +639,9 @@
{
LogState *logState;
int fd = -1;
+ DECLARE_SIGSET(sigflags);
- lock();
+ lock(&sigflags);
logState = createLogState();
if (logState != NULL) {
@@ -632,7 +651,7 @@
errno = ENFILE;
}
- unlock();
+ unlock(&sigflags);
return fd;
}
diff --git a/liblog/log_is_loggable.c b/liblog/log_is_loggable.c
index 814d96d..9d043ff 100644
--- a/liblog/log_is_loggable.c
+++ b/liblog/log_is_loggable.c
@@ -16,12 +16,39 @@
#include <ctype.h>
#include <pthread.h>
+#include <signal.h>
#include <stdlib.h>
#include <string.h>
#define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_
#include <sys/_system_properties.h>
#include <android/log.h>
+#include <log/log.h>
+
+static pthread_mutex_t lock_loggable = PTHREAD_MUTEX_INITIALIZER;
+
+static void lock(sigset_t *sigflags)
+{
+ /*
+ * If we trigger a signal handler in the middle of locked activity and the
+ * signal handler logs a message, we could get into a deadlock state.
+ */
+ if (sigflags) {
+ sigset_t all;
+
+ sigfillset(&all);
+ pthread_sigmask(SIG_BLOCK, &all, sigflags);
+ }
+ pthread_mutex_lock(&lock_loggable);
+}
+
+static void unlock(sigset_t *sigflags)
+{
+ pthread_mutex_unlock(&lock_loggable);
+ if (sigflags) {
+ pthread_sigmask(SIG_UNBLOCK, sigflags, NULL);
+ }
+}
struct cache {
const prop_info *pinfo;
@@ -49,9 +76,7 @@
cache->c = buf[0];
}
-static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
-
-static int __android_log_level(const char *tag, int def)
+static int __android_log_level(const char *tag, int flag)
{
/* sizeof() is used on this array below */
static const char log_namespace[] = "persist.log.tag.";
@@ -83,10 +108,11 @@
{ NULL, -1, 0 },
{ NULL, -1, 0 }
};
+ sigset_t sigflags;
strcpy(key, log_namespace);
- pthread_mutex_lock(&lock);
+ lock((flag & ANDROID_LOGGABLE_FLAG_NOT_WITHIN_SIGNAL) ? NULL : &sigflags);
current_global_serial = __system_property_area_serial();
@@ -156,7 +182,7 @@
global_serial = current_global_serial;
- pthread_mutex_unlock(&lock);
+ unlock((flag & ANDROID_LOGGABLE_FLAG_NOT_WITHIN_SIGNAL) ? NULL : &sigflags);
switch (toupper(c)) {
case 'V': return ANDROID_LOG_VERBOSE;
@@ -168,36 +194,46 @@
case 'A': return ANDROID_LOG_FATAL;
case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
}
- return def;
+ return flag & ANDROID_LOGGABLE_FLAG_DEFAULT_MASK;
}
-int __android_log_is_loggable(int prio, const char *tag, int def)
+int __android_log_is_loggable(int prio, const char *tag, int flag)
{
- int logLevel = __android_log_level(tag, def);
+ int logLevel = __android_log_level(tag, flag);
return logLevel >= 0 && prio >= logLevel;
}
+/*
+ * Timestamp state generally remains constant, since a change is
+ * rare, we can accept a trylock failure gracefully.
+ */
+static pthread_mutex_t lock_timestamp = PTHREAD_MUTEX_INITIALIZER;
+
char android_log_timestamp()
{
static struct cache r_time_cache = { NULL, -1, 0 };
static struct cache p_time_cache = { NULL, -1, 0 };
- static uint32_t serial;
- uint32_t current_serial;
char retval;
- pthread_mutex_lock(&lock);
+ if (pthread_mutex_trylock(&lock_timestamp)) {
+ /* We are willing to accept some race in this context */
+ if (!(retval = p_time_cache.c)) {
+ retval = r_time_cache.c;
+ }
+ } else {
+ static uint32_t serial;
+ uint32_t current_serial = __system_property_area_serial();
+ if (current_serial != serial) {
+ refresh_cache(&r_time_cache, "ro.logd.timestamp");
+ refresh_cache(&p_time_cache, "persist.logd.timestamp");
+ serial = current_serial;
+ }
+ if (!(retval = p_time_cache.c)) {
+ retval = r_time_cache.c;
+ }
- current_serial = __system_property_area_serial();
- if (current_serial != serial) {
- refresh_cache(&r_time_cache, "ro.logd.timestamp");
- refresh_cache(&p_time_cache, "persist.logd.timestamp");
- serial = current_serial;
+ pthread_mutex_unlock(&lock_timestamp);
}
- if (!(retval = p_time_cache.c)) {
- retval = r_time_cache.c;
- }
-
- pthread_mutex_unlock(&lock);
return tolower(retval ?: 'r');
}
diff --git a/liblog/logd_write.c b/liblog/logd_write.c
index a4310ae..a8ecc8d 100644
--- a/liblog/logd_write.c
+++ b/liblog/logd_write.c
@@ -20,6 +20,7 @@
#include <fcntl.h>
#if !defined(_WIN32)
#include <pthread.h>
+#include <signal.h>
#endif
#include <stdarg.h>
#include <stdatomic.h>
@@ -54,14 +55,43 @@
static int __write_to_log_init(log_id_t, struct iovec *vec, size_t nr);
static int (*write_to_log)(log_id_t, struct iovec *vec, size_t nr) = __write_to_log_init;
-#if !defined(_WIN32)
-static pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
-#endif
#ifndef __unused
#define __unused __attribute__((__unused__))
#endif
+#if !defined(_WIN32)
+static pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
+
+static void lock(sigset_t *sigflags)
+{
+ /*
+ * If we trigger a signal handler in the middle of locked activity and the
+ * signal handler logs a message, we could get into a deadlock state.
+ */
+ sigset_t all;
+
+ sigfillset(&all);
+ pthread_sigmask(SIG_BLOCK, &all, sigflags);
+ pthread_mutex_lock(&log_init_lock);
+}
+
+static void unlock(sigset_t *sigflags)
+{
+ pthread_mutex_unlock(&log_init_lock);
+ pthread_sigmask(SIG_UNBLOCK, sigflags, NULL);
+}
+
+#define DECLARE_SIGSET(name) sigset_t name
+
+#else /* !defined(_WIN32) */
+
+#define lock(sigflags) ((void)0)
+#define unlock(sigflags) ((void)0)
+#define DECLARE_SIGSET(name)
+
+#endif /* !defined(_WIN32) */
+
#if FAKE_LOG_DEVICE
static int log_fds[(int)LOG_ID_MAX] = { -1, -1, -1, -1, -1 };
#else
@@ -275,17 +305,15 @@
*/
ret = TEMP_FAILURE_RETRY(writev(logd_fd, newVec + 1, i - 1));
if (ret < 0) {
+ DECLARE_SIGSET(sigflags);
+
ret = -errno;
if (ret == -ENOTCONN) {
-#if !defined(_WIN32)
- pthread_mutex_lock(&log_init_lock);
-#endif
+ lock(&sigflags);
close(logd_fd);
logd_fd = -1;
ret = __write_to_log_initialize();
-#if !defined(_WIN32)
- pthread_mutex_unlock(&log_init_lock);
-#endif
+ unlock(&sigflags);
if (ret < 0) {
return ret;
@@ -329,18 +357,16 @@
static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
{
-#if !defined(_WIN32)
- pthread_mutex_lock(&log_init_lock);
-#endif
+ DECLARE_SIGSET(sigflags);
+
+ lock(&sigflags);
if (write_to_log == __write_to_log_init) {
int ret;
ret = __write_to_log_initialize();
if (ret < 0) {
-#if !defined(_WIN32)
- pthread_mutex_unlock(&log_init_lock);
-#endif
+ unlock(&sigflags);
#if (FAKE_LOG_DEVICE == 0)
if (pstore_fd >= 0) {
__write_to_log_daemon(log_id, vec, nr);
@@ -352,9 +378,7 @@
write_to_log = __write_to_log_daemon;
}
-#if !defined(_WIN32)
- pthread_mutex_unlock(&log_init_lock);
-#endif
+ unlock(&sigflags);
return write_to_log(log_id, vec, nr);
}
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index fd5c066..c2f71d1 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -191,7 +191,9 @@
prio = *msg;
tag = msg + 1;
}
- if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) {
+ if (!__android_log_is_loggable(prio, tag,
+ ANDROID_LOG_VERBOSE |
+ ANDROID_LOGGABLE_FLAG_NOT_WITHIN_SIGNAL)) {
// Log traffic received to total
pthread_mutex_lock(&mLogElementsLock);
stats.add(elem);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index c4c302b..f10dccf 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -107,7 +107,9 @@
LogBuffer *parent) {
static const char tag[] = "chatty";
- if (!__android_log_is_loggable(ANDROID_LOG_INFO, tag, ANDROID_LOG_VERBOSE)) {
+ if (!__android_log_is_loggable(ANDROID_LOG_INFO, tag,
+ ANDROID_LOG_VERBOSE |
+ ANDROID_LOGGABLE_FLAG_NOT_WITHIN_SIGNAL)) {
return 0;
}