Merge "liblog: resolve deadlocks"

This commit is contained in:
Mark Salyzyn 2015-11-13 15:16:49 +00:00 committed by Gerrit Code Review
commit 5559f1d6e8
6 changed files with 141 additions and 53 deletions

View file

@ -616,7 +616,12 @@ typedef enum log_id {
* 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);

View file

@ -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 @@ typedef struct LogState {
*/
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 LogState *fdToLogState(int fd)
static void deleteFakeFd(int fd)
{
LogState *ls;
DECLARE_SIGSET(sigflags);
lock();
lock(&sigflags);
ls = fdToLogState(fd);
if (ls != NULL) {
@ -164,7 +181,7 @@ static void deleteFakeFd(int fd)
free(ls);
}
unlock();
unlock(&sigflags);
}
/*
@ -548,12 +565,13 @@ static void showLog(LogState *state,
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 @@ static ssize_t logWritev(int fd, const struct iovec* vector, int count)
}
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 @@ static int logOpen(const char* pathName, int flags __unused)
{
LogState *logState;
int fd = -1;
DECLARE_SIGSET(sigflags);
lock();
lock(&sigflags);
logState = createLogState();
if (logState != NULL) {
@ -632,7 +651,7 @@ static int logOpen(const char* pathName, int flags __unused)
errno = ENFILE;
}
unlock();
unlock(&sigflags);
return fd;
}

View file

@ -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 @@ static void refresh_cache(struct cache *cache, const char *key)
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 @@ static int __android_log_level(const char *tag, int def)
{ 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 @@ static int __android_log_level(const char *tag, int def)
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 @@ static int __android_log_level(const char *tag, int def)
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');
}

View file

@ -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 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr)
*/
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 @@ const char *android_log_id_to_name(log_id_t log_id)
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 @@ static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
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);
}

View file

@ -191,7 +191,9 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
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);

View file

@ -107,7 +107,9 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
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;
}