From 807e40ecc9786755e2f74a7a6a9b20c812588119 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 22 Sep 2016 09:56:51 -0700 Subject: [PATCH] liblog: logd: Add android_lookupEventTag_len() Allows us to mitigate the impact of MAP_PRIVATE and copy on write by calling android_lookupEventTag_len instead of android_lookupEventTag, and delaying the copy on write impact to the later. We return a string length in a supplied location along with the string pointer with android_lookupEventTag_len(const EventTagMap* map, size_t* len, int tag). The string is not guaranteed to be nul terminated. Since android_lookupEventTag() called even once can cause the memory impact, we will mark it as deprecated, but we currently have no timeframe for removal since this is a very old interface. Add an API for __android_log_is_loggable_len() that accepts the non null terminated content and fixup callers that would gain because the length is known prior to the call either in the compiler or at runtime. Tackle transition to android_lookupEventTag_len() and fixup callers. On any application that performs logging (eg: com.android.phone) /proc//smaps before: xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 463 /system/etc/event-log-tags Size: 20 kB Rss: 20 kB Pss: 1 kB Shared_Clean: 0 kB Shared_Dirty: 20 kB Private_Clean: 0 kB Private_Dirty: 0 kB Referenced: 0 kB Anonymous: 20 kB AnonHugePages: 0 kB Swap: 0 kB SwapPss: 0 kB KernelPageSize: 4 kB MMUPageSize: 4 kB Locked: 0 kB VmFlags: rd wr mr mw me ac /proc//smaps after: xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 1773 /system/etc/event-log-tags Size: 20 kB Rss: 20 kB Pss: 1 kB Shared_Clean: 20 kB (was 0kB) Shared_Dirty: 0 kB (was 20kB) Private_Clean: 0 kB Private_Dirty: 0 kB Referenced: 20 kB (was 0kB) Anonymous: 0 kB (was 20kB) AnonHugePages: 0 kB Swap: 0 kB SwapPss: 0 kB KernelPageSize: 4 kB MMUPageSize: 4 kB Locked: 0 kB VmFlags: rd wr mr mw me ac Added liblog-unit-tests --gtest_filter=liblog.event_log_tags to check for Shared_Clean: to not be 0 and Anonymous: to be 0 for all processes referencing event-log-tags. Which can include multiple references to /system/etc/event-log-tags and future possible refs to /data/misc/logd/event-log-tags and /dev/event-log-tags. We want failure messages to help point to errant code using the deprecated interface. This change saves 1/4MB of memory or more on a typical system. Test: gTest liblog-unit-tests Bug: 31456426 Change-Id: I9e08e44d9092bd96fe704b5709242e7195281d33 --- include/android/log.h | 7 +- include/log/event_tag_map.h | 9 +- include/log/logprint.h | 1 + liblog/event_tag_map.c | 52 ++++++--- liblog/fake_log_device.c | 9 ++ liblog/log_is_loggable.c | 35 ++++-- liblog/logd_writer.c | 6 +- liblog/logger_write.c | 14 ++- liblog/logprint.c | 34 +++--- liblog/tests/Android.mk | 4 +- liblog/tests/liblog_benchmark.cpp | 6 +- liblog/tests/liblog_test.cpp | 170 ++++++++++++++++++++++-------- logd/LogBuffer.cpp | 6 +- logd/LogBufferElement.cpp | 4 +- logd/LogStatistics.cpp | 7 +- logd/LogStatistics.h | 2 +- logd/LogUtils.h | 2 +- logd/main.cpp | 5 +- 18 files changed, 271 insertions(+), 102 deletions(-) diff --git a/include/android/log.h b/include/android/log.h index de5502a8f..5f20f8c5a 100644 --- a/include/android/log.h +++ b/include/android/log.h @@ -803,10 +803,12 @@ int android_log_destroy(android_log_context *ctx); */ #if LOG_NDEBUG /* Production */ #define android_testLog(prio, tag) \ - (__android_log_is_loggable(prio, tag, ANDROID_LOG_DEBUG) != 0) + (__android_log_is_loggable_len(prio, tag, (tag && *tag) ? strlen(tag) : 0, \ + ANDROID_LOG_DEBUG) != 0) #else #define android_testLog(prio, tag) \ - (__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE) != 0) + (__android_log_is_loggable_len(prio, tag, (tag && *tag) ? strlen(tag) : 0, \ + ANDROID_LOG_VERBOSE) != 0) #endif /* @@ -816,6 +818,7 @@ int android_log_destroy(android_log_context *ctx); * any other value. */ int __android_log_is_loggable(int prio, const char *tag, int default_prio); +int __android_log_is_loggable_len(int prio, const char *tag, size_t len, int default_prio); int __android_log_security(); /* Device Owner is present */ diff --git a/include/log/event_tag_map.h b/include/log/event_tag_map.h index 7ee0a7ca0..69774bacd 100644 --- a/include/log/event_tag_map.h +++ b/include/log/event_tag_map.h @@ -41,7 +41,14 @@ void android_closeEventTagMap(EventTagMap* map); /* * Look up a tag by index. Returns the tag string, or NULL if not found. */ -const char* android_lookupEventTag(const EventTagMap* map, unsigned int tag); +const char* android_lookupEventTag(const EventTagMap* map, unsigned int tag) + __attribute__((deprecated("use android_lookupEventTag_len() instead to minimize MAP_PRIVATE copy-on-write memory impact"))); + +/* + * Look up a tag by index. Returns the tag string & string length, or NULL if + * not found. Returned string is not guaranteed to be nul terminated. + */ +const char* android_lookupEventTag_len(const EventTagMap* map, size_t* len, unsigned int tag); #ifdef __cplusplus } diff --git a/include/log/logprint.h b/include/log/logprint.h index b8d8d4ccb..f70633d43 100644 --- a/include/log/logprint.h +++ b/include/log/logprint.h @@ -59,6 +59,7 @@ typedef struct AndroidLogEntry_t { int32_t pid; int32_t tid; const char * tag; + size_t tagLen; size_t messageLen; const char * message; } AndroidLogEntry; diff --git a/liblog/event_tag_map.c b/liblog/event_tag_map.c index c2dc74cd4..6705fb285 100644 --- a/liblog/event_tag_map.c +++ b/liblog/event_tag_map.c @@ -34,8 +34,9 @@ * Single entry. */ typedef struct EventTag { - uint32_t tagIndex; - const char* tagStr; + uint32_t tagIndex; + char* tagStr; + size_t tagLen; } EventTag; /* @@ -139,8 +140,9 @@ LIBLOG_ABI_PUBLIC void android_closeEventTagMap(EventTagMap* map) * * The entries are sorted by tag number, so we can do a binary search. */ -LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, - unsigned int tag) +LIBLOG_ABI_PUBLIC const char* android_lookupEventTag_len(const EventTagMap* map, + size_t *len, + unsigned int tag) { int lo = 0; int hi = map->numTags - 1; @@ -157,14 +159,36 @@ LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, hi = mid - 1; } else { /* found */ + if (len) *len = map->tagArray[mid].tagLen; + /* + * b/31456426 to check if gTest can detect copy-on-write issue + * add the following line to break us: + * map->tagArray[mid].tagStr[map->tagArray[mid].tagLen] = '\0'; + * or explicitly use deprecated android_lookupEventTag(). + */ return map->tagArray[mid].tagStr; } } errno = ENOENT; + if (len) *len = 0; return NULL; } +LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, + unsigned int tag) +{ + size_t len; + const char* tagStr = android_lookupEventTag_len(map, &len, tag); + char* cp; + + if (!tagStr) return tagStr; + cp = (char*)tagStr; + cp += len; + if (*cp) *cp = '\0'; /* Trigger copy on write :-( */ + return tagStr; +} + /* * Crunch through the file, parsing the contents and creating a tag index. */ @@ -337,19 +361,13 @@ static int scanTagLine(char** pData, EventTag* tag, int lineNum) /* Determine whether "c" is a valid tag char. */ while (isalnum(*++cp) || (*cp == '_')) { } + tag->tagLen = cp - tag->tagStr; - if (*cp == '\n') { - /* null terminate and return */ - *cp = '\0'; - } else if (isspace(*cp)) { - /* CRLF or trailin spaces; zap this char, then scan for the '\n' */ - *cp = '\0'; - + if (isspace(*cp)) { /* just ignore the rest of the line till \n TODO: read the tag description that follows the tag name */ - while (*++cp != '\n') { - } + while (*cp != '\n') ++cp; } else { fprintf(stderr, "%s: invalid tag chars on line %d\n", OUT_TAG, lineNum); errno = EINVAL; @@ -387,10 +405,12 @@ static int sortTags(EventTagMap* map) for (i = 1; i < map->numTags; i++) { if (map->tagArray[i].tagIndex == map->tagArray[i - 1].tagIndex) { fprintf(stderr, - "%s: duplicate tag entries (%" PRIu32 ":%s and %" PRIu32 ":%s)\n", + "%s: duplicate tag entries (%" PRIu32 ":%.*s and %" PRIu32 ":%.*s)\n", OUT_TAG, - map->tagArray[i].tagIndex, map->tagArray[i].tagStr, - map->tagArray[i - 1].tagIndex, map->tagArray[i - 1].tagStr); + map->tagArray[i].tagIndex, (int)map->tagArray[i].tagLen, + map->tagArray[i].tagStr, + map->tagArray[i - 1].tagIndex, (int)map->tagArray[i - 1].tagLen, + map->tagArray[i - 1].tagStr); errno = EMLINK; return -1; } diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c index 1b57e7550..7bd1f83d4 100644 --- a/liblog/fake_log_device.c +++ b/liblog/fake_log_device.c @@ -718,3 +718,12 @@ LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio, int logLevel = def; return logLevel >= 0 && prio >= logLevel; } + +LIBLOG_ABI_PUBLIC int __android_log_is_loggable_len(int prio, + const char *tag __unused, + size_t len __unused, + int def) +{ + int logLevel = def; + return logLevel >= 0 && prio >= logLevel; +} diff --git a/liblog/log_is_loggable.c b/liblog/log_is_loggable.c index bd8d5af95..4af8507a2 100644 --- a/liblog/log_is_loggable.c +++ b/liblog/log_is_loggable.c @@ -85,13 +85,13 @@ static void refresh_cache(struct cache *cache, const char *key) } } -static int __android_log_level(const char *tag, int default_prio) +static int __android_log_level(const char *tag, size_t len, int default_prio) { /* 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; + const size_t taglen = tag ? len : 0; /* sizeof(log_namespace) = strlen(log_namespace) + 1 */ char key[sizeof(log_namespace) + taglen]; /* may be > PROPERTY_KEY_MAX */ char *kp; @@ -147,7 +147,11 @@ static int __android_log_level(const char *tag, int default_prio) if (!not_locked) { if (!last_tag[0] || (last_tag[0] != tag[0]) - || strncmp(last_tag + 1, tag + 1, sizeof(last_tag) - 1)) { + || strncmp(last_tag + 1, tag + 1, + (len < sizeof(last_tag)) ? + (len - 1) : + (sizeof(last_tag) - 1)) + || ((len < sizeof(last_tag)) && last_tag[len])) { /* invalidate log.tag. cache */ for (i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) { tag_cache[i].pinfo = NULL; @@ -157,10 +161,16 @@ static int __android_log_level(const char *tag, int default_prio) local_change_detected = 1; } if (!last_tag[0]) { - strncpy(last_tag, tag, sizeof(last_tag)); + if (len < sizeof(last_tag)) { + strncpy(last_tag, tag, len); + last_tag[len] = '\0'; + } else { + strncpy(last_tag, tag, sizeof(last_tag)); + } } } - strcpy(key + sizeof(log_namespace) - 1, tag); + strncpy(key + sizeof(log_namespace) - 1, tag, len); + key[sizeof(log_namespace) - 1 + len] = '\0'; kp = key; for (i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) { @@ -246,10 +256,21 @@ static int __android_log_level(const char *tag, int default_prio) return default_prio; } -LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio, const char *tag, +LIBLOG_ABI_PUBLIC int __android_log_is_loggable_len(int prio, + const char *tag, size_t len, + int default_prio) +{ + int logLevel = __android_log_level(tag, len, default_prio); + return logLevel >= 0 && prio >= logLevel; +} + +LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio, + const char *tag, int default_prio) { - int logLevel = __android_log_level(tag, default_prio); + int logLevel = __android_log_level(tag, + (tag && *tag) ? strlen(tag) : 0, + default_prio); return logLevel >= 0 && prio >= logLevel; } diff --git a/liblog/logd_writer.c b/liblog/logd_writer.c index ebf8b3e46..e8e392d24 100644 --- a/liblog/logd_writer.c +++ b/liblog/logd_writer.c @@ -181,9 +181,9 @@ 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(ANDROID_LOG_INFO, - "liblog", - ANDROID_LOG_VERBOSE)) { + if (snapshot && __android_log_is_loggable_len(ANDROID_LOG_INFO, + "liblog", strlen("liblog"), + ANDROID_LOG_VERBOSE)) { android_log_event_int_t buffer; header.id = LOG_ID_EVENTS; diff --git a/liblog/logger_write.c b/liblog/logger_write.c index 4999aef0d..1e56b270b 100644 --- a/liblog/logger_write.c +++ b/liblog/logger_write.c @@ -279,6 +279,7 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) } } else if (log_id == LOG_ID_EVENTS) { const char *tag; + size_t len; EventTagMap *m, *f; if (vec[0].iov_len < 4) { @@ -286,6 +287,7 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) } tag = NULL; + len = 0; f = NULL; m = (EventTagMap *)atomic_load(&tagMap); @@ -308,11 +310,11 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) } } if (m && (m != (EventTagMap *)(uintptr_t)-1LL)) { - tag = android_lookupEventTag(m, get4LE(vec[0].iov_base)); + tag = android_lookupEventTag_len(m, &len, get4LE(vec[0].iov_base)); } - ret = __android_log_is_loggable(ANDROID_LOG_INFO, - tag, - ANDROID_LOG_VERBOSE); + ret = __android_log_is_loggable_len(ANDROID_LOG_INFO, + tag, len, + ANDROID_LOG_VERBOSE); if (f) { /* local copy marked for close */ android_closeEventTagMap(f); } @@ -345,7 +347,9 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) tag = NULL; } - if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { + if (!__android_log_is_loggable_len(prio, + tag, len - 1, + ANDROID_LOG_VERBOSE)) { return -EPERM; } } diff --git a/liblog/logprint.c b/liblog/logprint.c index d857090ef..2c4e619e4 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -539,6 +539,7 @@ LIBLOG_ABI_PUBLIC int android_log_processLogBuffer( entry->priority = msg[0]; entry->tag = msg + 1; + entry->tagLen = msgStart - 1; entry->message = msg + msgStart; entry->messageLen = (msgEnd < msgStart) ? 0 : (msgEnd - msgStart); @@ -801,8 +802,9 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer( eventData += 4; inCount -= 4; + entry->tagLen = 0; if (map != NULL) { - entry->tag = android_lookupEventTag(map, tagIndex); + entry->tag = android_lookupEventTag_len(map, &entry->tagLen, tagIndex); } else { entry->tag = NULL; } @@ -813,12 +815,16 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer( * shift the buffer pointers down. */ if (entry->tag == NULL) { - int tagLen; + size_t tagLen; tagLen = snprintf(messageBuf, messageBufLen, "[%d]", tagIndex); + if (tagLen >= (size_t)messageBufLen) { + tagLen = messageBufLen - 1; + } entry->tag = messageBuf; - messageBuf += tagLen+1; - messageBufLen -= tagLen+1; + entry->tagLen = tagLen; + messageBuf += tagLen + 1; + messageBufLen -= tagLen + 1; } /* @@ -1386,13 +1392,13 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine ( switch (p_format->format) { case FORMAT_TAG: len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, - "%c/%-8s: ", priChar, entry->tag); + "%c/%-8.*s: ", priChar, (int)entry->tagLen, entry->tag); strcpy(suffixBuf + suffixLen, "\n"); ++suffixLen; break; case FORMAT_PROCESS: len = snprintf(suffixBuf + suffixLen, sizeof(suffixBuf) - suffixLen, - " (%s)\n", entry->tag); + " (%.*s)\n", (int)entry->tagLen, entry->tag); suffixLen += MIN(len, sizeof(suffixBuf) - suffixLen); len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, "%c(%s%5d) ", priChar, uid, entry->pid); @@ -1411,8 +1417,8 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine ( break; case FORMAT_TIME: len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, - "%s %c/%-8s(%s%5d): ", timeBuf, priChar, entry->tag, - uid, entry->pid); + "%s %c/%-8.*s(%s%5d): ", timeBuf, priChar, + (int)entry->tagLen, entry->tag, uid, entry->pid); strcpy(suffixBuf + suffixLen, "\n"); ++suffixLen; break; @@ -1422,15 +1428,16 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine ( *ret = ' '; } len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, - "%s %s%5d %5d %c %-8s: ", timeBuf, - uid, entry->pid, entry->tid, priChar, entry->tag); + "%s %s%5d %5d %c %-8.*s: ", timeBuf, uid, entry->pid, + entry->tid, priChar, (int)entry->tagLen, entry->tag); strcpy(suffixBuf + suffixLen, "\n"); ++suffixLen; break; case FORMAT_LONG: len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, - "[ %s %s%5d:%5d %c/%-8s ]\n", - timeBuf, uid, entry->pid, entry->tid, priChar, entry->tag); + "[ %s %s%5d:%5d %c/%-8.*s ]\n", + timeBuf, uid, entry->pid, entry->tid, priChar, + (int)entry->tagLen, entry->tag); strcpy(suffixBuf + suffixLen, "\n\n"); suffixLen += 2; prefixSuffixIsHeaderFooter = 1; @@ -1438,7 +1445,8 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine ( case FORMAT_BRIEF: default: len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen, - "%c/%-8s(%s%5d): ", priChar, entry->tag, uid, entry->pid); + "%c/%-8.*s(%s%5d): ", priChar, (int)entry->tagLen, entry->tag, + uid, entry->pid); strcpy(suffixBuf + suffixLen, "\n"); ++suffixLen; break; diff --git a/liblog/tests/Android.mk b/liblog/tests/Android.mk index 8229859a2..a755b980c 100644 --- a/liblog/tests/Android.mk +++ b/liblog/tests/Android.mk @@ -40,7 +40,7 @@ include $(CLEAR_VARS) LOCAL_MODULE := $(test_module_prefix)benchmarks LOCAL_MODULE_TAGS := $(test_tags) LOCAL_CFLAGS += $(benchmark_c_flags) -LOCAL_SHARED_LIBRARIES += liblog libm +LOCAL_SHARED_LIBRARIES += liblog libm libbase LOCAL_SRC_FILES := $(benchmark_src_files) include $(BUILD_NATIVE_TEST) @@ -73,6 +73,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 libcutils +LOCAL_SHARED_LIBRARIES := liblog libcutils libbase LOCAL_SRC_FILES := $(test_src_files) include $(BUILD_NATIVE_TEST) diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index 7561d8f0d..cd012ce69 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp @@ -650,10 +650,14 @@ BENCHMARK(BM_log_delay); * Measure the time it takes for __android_log_is_loggable. */ static void BM_is_loggable(int iters) { + static const char logd[] = "logd"; + StartBenchmarkTiming(); for (int i = 0; i < iters; ++i) { - __android_log_is_loggable(ANDROID_LOG_WARN, "logd", ANDROID_LOG_VERBOSE); + __android_log_is_loggable_len(ANDROID_LOG_WARN, + logd, strlen(logd), + ANDROID_LOG_VERBOSE); } StopBenchmarkTiming(); diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 6e709a948..b1dae9ebe 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -14,6 +14,8 @@ * limitations under the License. */ +#include +#include #include #include #include @@ -22,7 +24,11 @@ #include #include +#include + #include +#include +#include #include #include #include @@ -1337,8 +1343,8 @@ TEST(liblog, is_loggable) { continue; } fprintf(stderr, "i=%zu j=%zu\r", i, j); - bool android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, levels[j].level); + bool android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), levels[j].level); if ((levels[i].level < levels[j].level) || (levels[j].level == -1)) { if (android_log_is_loggable) { @@ -1346,8 +1352,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, levels[j].level)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), levels[j].level)); } } else { if (!android_log_is_loggable) { @@ -1355,8 +1361,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, levels[j].level)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), levels[j].level)); } } } @@ -1377,8 +1383,8 @@ TEST(liblog, is_loggable) { i, j, key, buf); usleep(20000); property_set(key, buf); - bool android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + bool android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_DEBUG) @@ -1388,8 +1394,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1397,8 +1403,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -1407,8 +1413,8 @@ TEST(liblog, is_loggable) { fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key + base_offset, buf); property_set(key + base_offset, buf); - android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_DEBUG) @@ -1418,8 +1424,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1427,8 +1433,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -1439,8 +1445,8 @@ TEST(liblog, is_loggable) { fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key, buf); property_set(key, buf); - android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_DEBUG) @@ -1450,8 +1456,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1459,8 +1465,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -1469,8 +1475,8 @@ TEST(liblog, is_loggable) { fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key + base_offset, buf); property_set(key + base_offset, buf); - android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_DEBUG) @@ -1480,8 +1486,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1489,8 +1495,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -1517,8 +1523,8 @@ TEST(liblog, is_loggable) { i, j, key, buf); usleep(20000); property_set(key, buf); - bool android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + bool android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO @@ -1528,8 +1534,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1537,8 +1543,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -1547,8 +1553,8 @@ TEST(liblog, is_loggable) { fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key + base_offset, buf); property_set(key + base_offset, buf); - android_log_is_loggable = __android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG); + android_log_is_loggable = __android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG); if ((levels[i].level < levels[j].level) || (levels[j].level == -1) || ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO @@ -1558,8 +1564,8 @@ TEST(liblog, is_loggable) { } EXPECT_FALSE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_FALSE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_FALSE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } else { if (!android_log_is_loggable) { @@ -1567,8 +1573,8 @@ TEST(liblog, is_loggable) { } EXPECT_TRUE(android_log_is_loggable); for(size_t k = 10; k; --k) { - EXPECT_TRUE(__android_log_is_loggable( - levels[i].level, tag, ANDROID_LOG_DEBUG)); + EXPECT_TRUE(__android_log_is_loggable_len( + levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG)); } } usleep(20000); @@ -2617,3 +2623,83 @@ TEST(liblog, __android_log_pmsg_file_read) { EXPECT_LT(0, ret); EXPECT_EQ(1U, signaled); } + +// 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); +} + +static void event_log_tags_test_smap(pid_t pid) { + std::string filename = android::base::StringPrintf("/proc/%d/smaps", pid); + + std::string content; + if (!android::base::ReadFileToString(filename, &content)) return; + + bool shared_ok = false; + bool anonymous_ok = false; + bool pass_ok = false; + + static const char event_log_tags[] = "event-log-tags"; + std::string::size_type pos = 0; + while ((pos = content.find(event_log_tags, pos)) != std::string::npos) { + pos += strlen(event_log_tags); + + // must not be: 'Shared_Clean: 0 kB' + static const char shared_clean[] = "Shared_Clean:"; + std::string::size_type clean = content.find(shared_clean, pos); + bool ok = (clean != std::string::npos) && + ((clean = content.find_first_not_of(" \t", clean + + strlen(shared_clean))) != std::string::npos) && + (content.find_first_not_of("123456789", clean) != clean); + if (ok && !pass_ok) { + shared_ok = true; + } else if (!ok) { + shared_ok = false; + } + + // must be: 'Anonymous: 0 kB' + static const char anonymous[] = "Anonymous:"; + std::string::size_type anon = content.find(anonymous, pos); + ok = (anon != std::string::npos) && + ((anon = content.find_first_not_of(" \t", anon + + strlen(anonymous))) != std::string::npos) && + (content.find_first_not_of("0", anon) != anon); + if (ok && !pass_ok) { + anonymous_ok = true; + } else if (!ok) { + anonymous_ok = false; + } + + pass_ok = true; + } + content = ""; + + if (!pass_ok) return; + if (shared_ok && anonymous_ok) return; + + filename = android::base::StringPrintf("/proc/%d/comm", pid); + android::base::ReadFileToString(filename, &content); + content = android::base::StringPrintf("%d:%s", + pid, content.substr(0, content.find("\n")).c_str()); + + EXPECT_TRUE(IsOk(shared_ok, content)); + EXPECT_TRUE(IsOk(anonymous_ok, content)); +} + +TEST(liblog, event_log_tags) { + std::unique_ptr proc_dir(opendir("/proc"), closedir); + ASSERT_FALSE(!proc_dir); + + dirent* e; + while ((e = readdir(proc_dir.get()))) { + if (e->d_type != DT_DIR) continue; + if (!isdigit(e->d_name[0])) continue; + long long id = atoll(e->d_name); + if (id <= 0) continue; + pid_t pid = id; + if (id != pid) continue; + event_log_tags_test_smap(pid); + } +} diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 1ecf99c98..7f5fe4f8f 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -211,13 +211,15 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, if (log_id != LOG_ID_SECURITY) { int prio = ANDROID_LOG_INFO; const char *tag = NULL; + size_t len = 0; if (log_id == LOG_ID_EVENTS) { - tag = android::tagToName(elem->getTag()); + tag = android::tagToName(&len, elem->getTag()); } else { prio = *msg; tag = msg + 1; + len = strlen(tag); } - if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { + if (!__android_log_is_loggable_len(prio, tag, len, ANDROID_LOG_VERBOSE)) { // Log traffic received to total pthread_mutex_lock(&mLogElementsLock); stats.add(elem); diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 3e6e5864f..e5de11d92 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -110,7 +110,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_len(ANDROID_LOG_INFO, + tag, strlen(tag), + ANDROID_LOG_VERBOSE)) { return 0; } diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 86d33b26d..c6ebd52dc 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -436,11 +436,12 @@ std::string TagEntry::format(const LogStatistics & /* stat */, log_id_t /* id */ name = android::base::StringPrintf("%7u/%u", getKey(), uid); } - const char *nameTmp = getName(); + size_t len = 0; + const char *nameTmp = getName(len); if (nameTmp) { name += android::base::StringPrintf( - "%*s%s", (int)std::max(14 - name.length(), (size_t)1), - "", nameTmp); + "%*s%.*s", (int)std::max(14 - name.length(), (size_t)1), + "", (int)len, nameTmp); } std::string size = android::base::StringPrintf("%zu", diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index e81195343..bfaafa461 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -385,7 +385,7 @@ struct TagEntry : public EntryBaseDropped { const uint32_t&getKey() const { return tag; } const pid_t&getPid() const { return pid; } const uid_t&getUid() const { return uid; } - const char*getName() const { return android::tagToName(tag); } + const char*getName(size_t &len) const { return android::tagToName(&len, tag); } inline void add(LogBufferElement *element) { if (uid != element->getUid()) { diff --git a/logd/LogUtils.h b/logd/LogUtils.h index 939515e9c..6db4c51d2 100644 --- a/logd/LogUtils.h +++ b/logd/LogUtils.h @@ -37,7 +37,7 @@ char *pidToName(pid_t pid); char *tidToName(pid_t tid); // Furnished in main.cpp. Thread safe. -const char *tagToName(uint32_t tag); +const char *tagToName(size_t *len, uint32_t tag); } diff --git a/logd/main.cpp b/logd/main.cpp index 77a69730d..a0cea25cf 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -302,7 +302,7 @@ void reinit_signal_handler(int /*signal*/) { } // tagToName converts an events tag into a name -const char *android::tagToName(uint32_t tag) { +const char *android::tagToName(size_t *len, uint32_t tag) { static const EventTagMap *map; if (!map) { @@ -312,10 +312,11 @@ const char *android::tagToName(uint32_t tag) { } sem_post(&sem_name); if (!map) { + if (len) len = 0; return NULL; } } - return android_lookupEventTag(map, tag); + return android_lookupEventTag_len(map, len, tag); } static void readDmesg(LogAudit *al, LogKlog *kl) {