Merge "liblog: resolve deadlocks" am: 5559f1d6e8

am: 650a06e01b

* commit '650a06e01bb3bf80a4223fcb9117f59fdcff4eb5':
  liblog: resolve deadlocks

include/log/log.h

@@ -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);

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 @@ 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;
 }

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 @@ 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 flag)
-
-static int __android_log_level(const char *tag, int def)
 {
     /* 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();
+        pthread_mutex_unlock(&lock_timestamp);
-    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;
-    }
-
-    pthread_mutex_unlock(&lock);
 
     return tolower(retval ?: 'r');
 }

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 @@ 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)
+            lock(&sigflags);
-            pthread_mutex_lock(&log_init_lock);
-#endif
             close(logd_fd);
             logd_fd = -1;
             ret = __write_to_log_initialize();
-#if !defined(_WIN32)
+            unlock(&sigflags);
-            pthread_mutex_unlock(&log_init_lock);
-#endif
 
             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)
+    DECLARE_SIGSET(sigflags);
-    pthread_mutex_lock(&log_init_lock);
+
-#endif
+    lock(&sigflags);
 
     if (write_to_log == __write_to_log_init) {
         int ret;
 
         ret = __write_to_log_initialize();
         if (ret < 0) {
-#if !defined(_WIN32)
+            unlock(&sigflags);
-            pthread_mutex_unlock(&log_init_lock);
-#endif
 #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)
+    unlock(&sigflags);
-    pthread_mutex_unlock(&log_init_lock);
-#endif
 
     return write_to_log(log_id, vec, nr);
 }

logd/LogBuffer.cpp

@@ -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);

logd/LogBufferElement.cpp

@@ -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;
     }