liblog: __android_log_is_loggable support global properties

(cherry pick from commit c158456f50817ac506f4eed780978e63dd222fe4)

- Add support for "log.tag" and "persist.log.tag" global
  logging properties, effectively a runtime default minimum
  logging level.
- Add a thread-safe single level cache plus selective logic for the
  four properties being checked to help speed up logging decision
  on subsequent identical calls.
- Using new __system_property_area_serial() to make for
  efficient (<100ns) handling of cache misses. Despite adding
  two new properties, we are 8 times faster on subsequent calls
  even if the properties do not exist.
- A NULL or blank tag is no longer directed to return default,
  it will check the pair of global logging properties first.
- Add liblog.is_loggable gTest
- Fixup liblog.android_logger_get_, allow no content in crash buffer
- Fixup liblog.max_payload, lowered logd priority increases latency

Bug: 19544788
Bug: 21696721
Change-Id: Ideb887755aa3f1fd14a2603bda1fe23cba49642c

3 files changed, 334 insertions, 23 deletions

diff --git a/liblog/log_is_loggable.c b/liblog/log_is_loggable.c
index 2e09192..7a8e33f 100644
--- a/liblog/log_is_loggable.c
+++ b/liblog/log_is_loggable.c
@@ -15,41 +15,158 @@
 */
 
 #include <ctype.h>
+#include <pthread.h>
+#include <stdlib.h>
 #include <string.h>
-#include <sys/system_properties.h>
+#define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_
+#include <sys/_system_properties.h>
 
 #include <android/log.h>
 
-static int __android_log_level(const char *tag, int def)
+struct cache {
+    const prop_info *pinfo;
+    uint32_t serial;
+    char c;
+};
+
+static void refresh_cache(struct cache *cache, const char *key)
 {
+    uint32_t serial;
     char buf[PROP_VALUE_MAX];
 
-    if (!tag || !*tag) {
-        return def;
+    if (!cache->pinfo) {
+        cache->pinfo = __system_property_find(key);
+        if (!cache->pinfo) {
+            return;
+        }
+    }
+    serial = __system_property_serial(cache->pinfo);
+    if (serial == cache->serial) {
+        return;
     }
-    {
-        static const char log_namespace[] = "persist.log.tag.";
-        char key[sizeof(log_namespace) + strlen(tag)];
+    cache->serial = serial;
+    __system_property_read(cache->pinfo, 0, buf);
+    cache->c = buf[0];
+}
+
+static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
+
+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.";
+    static const size_t base_offset = 8; /* skip "persist." */
+    /* calculate the size of our key temporary buffer */
+    const size_t taglen = (tag && *tag) ? strlen(tag) : 0;
+    /* sizeof(log_namespace) = strlen(log_namespace) + 1 */
+    char key[sizeof(log_namespace) + taglen];
+    char *kp;
+    size_t i;
+    char c = 0;
+    /*
+     * Single layer cache of four properties. Priorities are:
+     *    log.tag.<tag>
+     *    persist.log.tag.<tag>
+     *    log.tag
+     *    persist.log.tag
+     * Where the missing tag matches all tags and becomes the
+     * system global default. We do not support ro.log.tag* .
+     */
+    static char *last_tag;
+    static uint32_t global_serial;
+    uint32_t current_global_serial;
+    static struct cache tag_cache[2] = {
+        { NULL, -1, 0 },
+        { NULL, -1, 0 }
+    };
+    static struct cache global_cache[2] = {
+        { NULL, -1, 0 },
+        { NULL, -1, 0 }
+    };
+
+    strcpy(key, log_namespace);
+
+    pthread_mutex_lock(&lock);
+
+    current_global_serial = __system_property_area_serial();
+
+    if (taglen) {
+        uint32_t current_local_serial = current_global_serial;
 
-        strcpy(key, log_namespace);
+        if (!last_tag || strcmp(last_tag, tag)) {
+            /* invalidate log.tag.<tag> cache */
+            for(i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) {
+                tag_cache[i].pinfo = NULL;
+                tag_cache[i].serial = -1;
+                tag_cache[i].c = '\0';
+            }
+            free(last_tag);
+            last_tag = NULL;
+            current_global_serial = -1;
+        }
+        if (!last_tag) {
+            last_tag = strdup(tag);
+        }
         strcpy(key + sizeof(log_namespace) - 1, tag);
 
-        if (__system_property_get(key + 8, buf) <= 0) {
-            buf[0] = '\0';
+        kp = key;
+        for(i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) {
+            if (current_local_serial != global_serial) {
+                refresh_cache(&tag_cache[i], kp);
+            }
+
+            if (tag_cache[i].c) {
+                c = tag_cache[i].c;
+                break;
+            }
+
+            kp = key + base_offset;
         }
-        if (!buf[0] && __system_property_get(key, buf) <= 0) {
-            buf[0] = '\0';
+    }
+
+    switch (toupper(c)) { /* if invalid, resort to global */
+    case 'V':
+    case 'D':
+    case 'I':
+    case 'W':
+    case 'E':
+    case 'F': /* Not officially supported */
+    case 'A':
+    case 'S':
+        break;
+    default:
+        /* clear '.' after log.tag */
+        key[sizeof(log_namespace) - 2] = '\0';
+
+        kp = key;
+        for(i = 0; i < (sizeof(global_cache) / sizeof(global_cache[0])); ++i) {
+            if (current_global_serial != global_serial) {
+                refresh_cache(&global_cache[i], kp);
+            }
+
+            if (global_cache[i].c) {
+                c = global_cache[i].c;
+                break;
+            }
+
+            kp = key + base_offset;
         }
+        break;
     }
-    switch (toupper(buf[0])) {
-        case 'V': return ANDROID_LOG_VERBOSE;
-        case 'D': return ANDROID_LOG_DEBUG;
-        case 'I': return ANDROID_LOG_INFO;
-        case 'W': return ANDROID_LOG_WARN;
-        case 'E': return ANDROID_LOG_ERROR;
-        case 'F': /* FALLTHRU */ /* Not officially supported */
-        case 'A': return ANDROID_LOG_FATAL;
-        case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
+
+    global_serial = current_global_serial;
+
+    pthread_mutex_unlock(&lock);
+
+    switch (toupper(c)) {
+    case 'V': return ANDROID_LOG_VERBOSE;
+    case 'D': return ANDROID_LOG_DEBUG;
+    case 'I': return ANDROID_LOG_INFO;
+    case 'W': return ANDROID_LOG_WARN;
+    case 'E': return ANDROID_LOG_ERROR;
+    case 'F': /* FALLTHRU */ /* Not officially supported */
+    case 'A': return ANDROID_LOG_FATAL;
+    case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
     }
     return def;
 }
diff --git a/liblog/tests/Android.mk b/liblog/tests/Android.mk
index d75bbc9..a407c50 100644
--- a/liblog/tests/Android.mk
+++ b/liblog/tests/Android.mk
@@ -77,6 +77,6 @@ include $(CLEAR_VARS)
 LOCAL_MODULE := $(test_module_prefix)unit-tests
 LOCAL_MODULE_TAGS := $(test_tags)
 LOCAL_CFLAGS += $(test_c_flags)
-LOCAL_SHARED_LIBRARIES := liblog
+LOCAL_SHARED_LIBRARIES := liblog libcutils
 LOCAL_SRC_FILES := $(test_src_files)
 include $(BUILD_NATIVE_TEST)
diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp
index 33f6481..abe0239 100644
--- a/liblog/tests/liblog_test.cpp
+++ b/liblog/tests/liblog_test.cpp
@@ -17,6 +17,8 @@
 #include <fcntl.h>
 #include <inttypes.h>
 #include <signal.h>
+
+#include <cutils/properties.h>
 #include <gtest/gtest.h>
 #include <log/log.h>
 #include <log/logger.h>
@@ -439,6 +441,7 @@ TEST(liblog, max_payload) {
 
     LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
                                               tag, max_payload_buf));
+    sleep(2);
 
     struct logger_list *logger_list;
 
@@ -603,10 +606,14 @@ TEST(liblog, android_logger_get_) {
         if (id != android_name_to_log_id(name)) {
             continue;
         }
+        fprintf(stderr, "log buffer %s\r", name);
         struct logger * logger;
         EXPECT_TRUE(NULL != (logger = android_logger_open(logger_list, id)));
         EXPECT_EQ(id, android_logger_get_id(logger));
-        EXPECT_LT(0, android_logger_get_log_size(logger));
+        /* crash buffer is allowed to be empty, that is actually healthy! */
+        if (android_logger_get_log_size(logger) || strcmp("crash", name)) {
+            EXPECT_LT(0, android_logger_get_log_size(logger));
+        }
         EXPECT_LT(0, android_logger_get_log_readable_size(logger));
         EXPECT_LT(0, android_logger_get_log_version(logger));
     }
@@ -682,3 +689,190 @@ TEST(liblog, filterRule) {
 
     android_log_format_free(p_format);
 }
+
+TEST(liblog, is_loggable) {
+    static const char tag[] = "is_loggable";
+    static const char log_namespace[] = "persist.log.tag.";
+    static const size_t base_offset = 8; /* skip "persist." */
+    // sizeof("string") = strlen("string") + 1
+    char key[sizeof(log_namespace) + sizeof(tag) - 1];
+    char hold[4][PROP_VALUE_MAX];
+    static const struct {
+        int level;
+        char type;
+    } levels[] = {
+        { ANDROID_LOG_VERBOSE, 'v' },
+        { ANDROID_LOG_DEBUG  , 'd' },
+        { ANDROID_LOG_INFO   , 'i' },
+        { ANDROID_LOG_WARN   , 'w' },
+        { ANDROID_LOG_ERROR  , 'e' },
+        { ANDROID_LOG_FATAL  , 'a' },
+        { -1                 , 's' },
+        { -2                 , 'g' }, // Illegal value, resort to default
+    };
+
+    // Set up initial test condition
+    memset(hold, 0, sizeof(hold));
+    snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
+    property_get(key, hold[0], "");
+    property_set(key, "");
+    property_get(key + base_offset, hold[1], "");
+    property_set(key + base_offset, "");
+    strcpy(key, log_namespace);
+    key[sizeof(log_namespace) - 2] = '\0';
+    property_get(key, hold[2], "");
+    property_set(key, "");
+    property_get(key, hold[3], "");
+    property_set(key + base_offset, "");
+
+    // All combinations of level and defaults
+    for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
+        if (levels[i].level == -2) {
+            continue;
+        }
+        for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
+            if (levels[j].level == -2) {
+                continue;
+            }
+            fprintf(stderr, "i=%zu j=%zu\r", i, j);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       levels[j].level));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      levels[j].level));
+            }
+        }
+    }
+
+    // All combinations of level and tag and global properties
+    for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
+        if (levels[i].level == -2) {
+            continue;
+        }
+        for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
+            char buf[2];
+            buf[0] = levels[j].type;
+            buf[1] = '\0';
+
+            snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key, buf);
+            property_set(key, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_DEBUG)
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key, "");
+
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key + base_offset, buf);
+            property_set(key + base_offset, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_DEBUG)
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key + base_offset, "");
+
+            strcpy(key, log_namespace);
+            key[sizeof(log_namespace) - 2] = '\0';
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key, buf);
+            property_set(key, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_DEBUG)
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key, "");
+
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key + base_offset, buf);
+            property_set(key + base_offset, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_DEBUG)
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key + base_offset, "");
+        }
+    }
+
+    // All combinations of level and tag properties, but with global set to INFO
+    strcpy(key, log_namespace);
+    key[sizeof(log_namespace) - 2] = '\0';
+    property_set(key, "I");
+    snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
+    for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
+        if (levels[i].level == -2) {
+            continue;
+        }
+        for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
+            char buf[2];
+            buf[0] = levels[j].type;
+            buf[1] = '\0';
+
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key, buf);
+            property_set(key, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key, "");
+
+            fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
+                    i, j, key + base_offset, buf);
+            property_set(key + base_offset, buf);
+            if ((levels[i].level < levels[j].level)
+                    || (levels[j].level == -1)
+                    || ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
+                        && (levels[j].level == -2))) {
+                EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
+                                                       ANDROID_LOG_DEBUG));
+            } else {
+                EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
+                                                      ANDROID_LOG_DEBUG));
+            }
+            property_set(key + base_offset, "");
+        }
+    }
+
+    // reset parms
+    snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
+    property_set(key, hold[0]);
+    property_set(key + base_offset, hold[1]);
+    strcpy(key, log_namespace);
+    key[sizeof(log_namespace) - 2] = '\0';
+    property_set(key, hold[2]);
+    property_set(key + base_offset, hold[3]);
+}