From 46186a7238973c4f60ffcf1af0e2bee737bef63d Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 14 Apr 2017 07:41:11 -0700 Subject: [PATCH 1/3] logcat: test: standardize rest() to let logs land when injecting Add an internal rest() function to set the standard for how long we should wait for a log message to land end to end into the logs. Add a retry on -EBUSY for all descriptive tests along with a rest() after log injection so the tests can try to survive heavy Denial Of Service (DOS) loads. Some of the resting was done at a coarse 1 second, when 200ms will do just fine. Fix a few pesky issues surrounding test reliability and correctness: - stdint.h include missing. - missing a logcat_executable, means logcatd.descriptive testing was testing logcat instead. - count of interfering tests is 3 now: logcat, liblogcat and logcatd, if they all run in the same PID, we have to not fail. - Added a missed opportunity to add uniqueness to logcat.descriptive sync test. Test: gTest logcat-unit-tests Bug: 31456426 Change-Id: Iaf2bee97878957f654613bb2e78e32379bb8d1b7 --- logcat/tests/logcat_test.cpp | 71 ++++++++++++++++++++++++------------ 1 file changed, 47 insertions(+), 24 deletions(-) diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index 21868f2c7..b2b051e66 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -17,6 +17,7 @@ #include #include #include +#include #include #include #include @@ -47,6 +48,16 @@ #define BIG_BUFFER (5 * 1024) +// rest(), let the logs settle. +// +// logd is in a background cgroup and under extreme load can take up to +// 3 seconds to land a log entry. Under moderate load we can do with 200ms. +static void rest() { + static const useconds_t restPeriod = 200000; + + usleep(restPeriod); +} + // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and // non-syscall libs. Since we are only using this in the emergency of // a signal to stuff a terminating code into the logs, we will spin rather @@ -70,7 +81,7 @@ TEST(logcat, buckets) { #undef LOG_TAG #define LOG_TAG "inject" RLOGE(logcat_executable ".buckets"); - sleep(1); + rest(); ASSERT_TRUE(NULL != (fp = logcat_popen( @@ -1412,7 +1423,7 @@ TEST(logcat, regex) { LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, logcat_regex_prefix "_aaaa")); // Let the logs settle - sleep(1); + rest(); ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); @@ -1450,8 +1461,7 @@ TEST(logcat, maxcount) { LOG_FAILURE_RETRY( __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); - // Let the logs settle - sleep(1); + rest(); ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); @@ -1476,8 +1486,7 @@ static bool End_to_End(const char* tag, const char* fmt, ...) static bool End_to_End(const char* tag, const char* fmt, ...) { logcat_define(ctx); - FILE* fp = logcat_popen(ctx, - "logcat" + FILE* fp = logcat_popen(ctx, logcat_executable " -v brief" " -b events" " -v descriptive" @@ -1523,13 +1532,12 @@ static bool End_to_End(const char* tag, const char* fmt, ...) { // Help us pinpoint where things went wrong ... fprintf(stderr, "Closest match for\n %s\n is\n %s", expect.c_str(), lastMatch.c_str()); - } else if (count > 2) { + } else if (count > 3) { fprintf(stderr, "Too many matches (%d) for %s\n", count, expect.c_str()); } - // Expect one the first time around as either liblogcat.descriptive or - // logcat.descriptive. Expect two the second time as the other. - return count == 1 || count == 2; + // Three different known tests, we can see pollution from the others + return count && (count <= 3); } TEST(logcat, descriptive) { @@ -1537,24 +1545,28 @@ TEST(logcat, descriptive) { uint32_t tagNo; const char* tagStr; }; + int ret; { static const struct tag hhgtg = { 42, "answer" }; android_log_event_list ctx(hhgtg.tagNo); static const char theAnswer[] = "what is five by seven"; ctx << theAnswer; - ctx.write(); + // crafted to rest at least once after, and rest between retries. + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE( End_to_End(hhgtg.tagStr, "to life the universe etc=%s", theAnswer)); } { static const struct tag sync = { 2720, "sync" }; - static const char id[] = "logcat.decriptive"; + static const char id[] = ___STRING(logcat) ".descriptive-sync"; { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)42 << (int32_t)-1 << (int32_t)0; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=42,source=-1,account=0]", id)); } @@ -1563,7 +1575,8 @@ TEST(logcat, descriptive) { { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)43 << (int64_t)-1 << (int32_t)0; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=43,-1,0]", id)); } @@ -1571,7 +1584,8 @@ TEST(logcat, descriptive) { { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)44 << (int32_t)-1 << (int64_t)0; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); fprintf(stderr, "Expect a \"Closest match\" message\n"); EXPECT_FALSE(End_to_End( sync.tagStr, "[id=%s,event=44,source=-1,account=0]", id)); @@ -1583,7 +1597,8 @@ TEST(logcat, descriptive) { { android_log_event_list ctx(sync.tagNo); ctx << (uint64_t)30 << (int32_t)2; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE( End_to_End(sync.tagStr, "[aggregation time=30ms,count=2]")); } @@ -1591,7 +1606,8 @@ TEST(logcat, descriptive) { { android_log_event_list ctx(sync.tagNo); ctx << (uint64_t)31570 << (int32_t)911; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE( End_to_End(sync.tagStr, "[aggregation time=31.57s,count=911]")); } @@ -1602,42 +1618,48 @@ TEST(logcat, descriptive) { { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)512; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=512B")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)3072; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=3KB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)2097152; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=2MB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)2097153; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=2097153B")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)1073741824; - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=1GB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)3221225472; // 3MB, but on purpose overflowed - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "current=-1GB")); } } @@ -1645,7 +1667,8 @@ TEST(logcat, descriptive) { { static const struct tag sync = { 27501, "notification_panel_hidden" }; android_log_event_list ctx(sync.tagNo); - ctx.write(); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "")); } } From 5768d3d9769c37ede68efa2f7df98bb146881e62 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 10 Nov 2016 10:24:44 -0800 Subject: [PATCH 2/3] liblog: logprint supports number of seconds time event field Add s to report time in seconds. The time could be a period, duration or monotonic, expanded to seconds, minutes, hours and days. gTest has to acquire a dynamic tag allocation as there are no users of this feature yet. Looking to the future, audio media logging has binary content similar to the binary events structures Android logging uses and they have a definition of a duration field in their internal binary logging, so may be of use when we unify the logs. Test: gTest logcat-unit-tests --gtest_filter=*.descriptive Bug: 31456426 Change-Id: I262c03775983b3bc7b1b00227ce2bb2b0f357bec --- liblog/event.logtags | 1 + liblog/logprint.c | 43 ++++++++++++++++++++++++++++++++++-- logcat/event.logtags | 1 + logcat/tests/logcat_test.cpp | 43 ++++++++++++++++++++++++++++++++++++ logd/event.logtags | 1 + 5 files changed, 87 insertions(+), 2 deletions(-) diff --git a/liblog/event.logtags b/liblog/event.logtags index 301e8858d..0a3b6501b 100644 --- a/liblog/event.logtags +++ b/liblog/event.logtags @@ -29,6 +29,7 @@ # 4: Number of allocations # 5: Id # 6: Percent +# s: Number of seconds (monotonic time) # Default value for data of type int/long is 2 (bytes). # # TODO: generate ".java" and ".h" files with integer constants from this file. diff --git a/liblog/logprint.c b/liblog/logprint.c index 2ade7b02c..b62f8b446 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -326,6 +326,7 @@ android_log_formatFromString(const char* formatString) { else if (!strcmp(formatString, "uid")) format = FORMAT_MODIFIER_UID; else if (!strcmp(formatString, "descriptive")) format = FORMAT_MODIFIER_DESCRIPT; /* clang-format on */ + #ifndef __MINGW32__ else { extern char* tzname[2]; @@ -637,7 +638,8 @@ enum objectType { TYPE_MILLISECONDS = '3', TYPE_ALLOCATIONS = '4', TYPE_ID = '5', - TYPE_PERCENT = '6' + TYPE_PERCENT = '6', + TYPE_MONOTONIC = 's' }; static int android_log_printBinaryEvent(const unsigned char** pEventData, @@ -651,7 +653,7 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, size_t outBufLen = *pOutBufLen; size_t outBufLenSave = outBufLen; unsigned char type; - size_t outCount; + size_t outCount = 0; int result = 0; const char* cp; size_t len; @@ -690,6 +692,7 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, * 4: Number of allocations * 5: Id * 6: Percent + * s: Number of seconds (monotonic time) * Default value for data of type int/long is 2 (bytes). */ if (!cp || !findChar(&cp, &len, '(')) { @@ -921,6 +924,42 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, outCount = snprintf(outBuf, outBufLen, "ms"); } break; + case TYPE_MONOTONIC: { + static const uint64_t minute = 60; + static const uint64_t hour = 60 * minute; + static const uint64_t day = 24 * hour; + + /* Repaint as unsigned seconds, minutes, hours ... */ + outBuf -= outCount; + outBufLen += outCount; + uint64_t val = lval; + if (val >= day) { + outCount = snprintf(outBuf, outBufLen, "%" PRIu64 "d ", val / day); + if (outCount >= outBufLen) break; + outBuf += outCount; + outBufLen -= outCount; + val = (val % day) + day; + } + if (val >= minute) { + if (val >= hour) { + outCount = snprintf(outBuf, outBufLen, "%" PRIu64 ":", + (val / hour) % (day / hour)); + if (outCount >= outBufLen) break; + outBuf += outCount; + outBufLen -= outCount; + } + outCount = + snprintf(outBuf, outBufLen, + (val >= hour) ? "%02" PRIu64 ":" : "%" PRIu64 ":", + (val / minute) % (hour / minute)); + if (outCount >= outBufLen) break; + outBuf += outCount; + outBufLen -= outCount; + } + outCount = snprintf(outBuf, outBufLen, + (val >= minute) ? "%02" PRIu64 : "%" PRIu64 "s", + val % minute); + } break; case TYPE_ALLOCATIONS: outCount = 0; /* outCount = snprintf(outBuf, outBufLen, " allocations"); */ diff --git a/logcat/event.logtags b/logcat/event.logtags index 9f053511b..efcc8179b 100644 --- a/logcat/event.logtags +++ b/logcat/event.logtags @@ -30,6 +30,7 @@ # 4: Number of allocations # 5: Id # 6: Percent +# s: Number of seconds (monotonic time) # Default value for data of type int/long is 2 (bytes). # # TODO: generate ".java" and ".h" files with integer constants from this file. diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index b2b051e66..33355e4f5 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -32,6 +32,7 @@ #include #include +#include #include #include @@ -1671,6 +1672,48 @@ TEST(logcat, descriptive) { EXPECT_LE(0, ret); EXPECT_TRUE(End_to_End(sync.tagStr, "")); } + + { + // Invent new entries because existing can not serve + EventTagMap* map = android_openEventTagMap(nullptr); + ASSERT_TRUE(nullptr != map); + static const char name[] = ___STRING(logcat) "_descriptive_monotonic"; + int myTag = android_lookupEventTagNum(map, name, "(new|1|s)", + ANDROID_LOG_UNKNOWN); + android_closeEventTagMap(map); + ASSERT_NE(-1, myTag); + + const struct tag sync = { (uint32_t)myTag, name }; + + { + android_log_event_list ctx(sync.tagNo); + ctx << (uint32_t)7; + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); + EXPECT_TRUE(End_to_End(sync.tagStr, "new=7s")); + } + { + android_log_event_list ctx(sync.tagNo); + ctx << (uint32_t)62; + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); + EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:02")); + } + { + android_log_event_list ctx(sync.tagNo); + ctx << (uint32_t)3673; + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); + EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:01:13")); + } + { + android_log_event_list ctx(sync.tagNo); + ctx << (uint32_t)(86400 + 7200 + 180 + 58); + for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); + EXPECT_LE(0, ret); + EXPECT_TRUE(End_to_End(sync.tagStr, "new=1d 2:03:58")); + } + } } static bool reportedSecurity(const char* command) { diff --git a/logd/event.logtags b/logd/event.logtags index 39063a982..fa13a628d 100644 --- a/logd/event.logtags +++ b/logd/event.logtags @@ -29,6 +29,7 @@ # 4: Number of allocations # 5: Id # 6: Percent +# s: Number of seconds (monotonic time) # Default value for data of type int/long is 2 (bytes). # # TODO: generate ".java" and ".h" files with integer constants from this file. From 01bdb04be63bce0c81d1d07a77699631e913ceb5 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 12 Apr 2017 15:11:24 -0700 Subject: [PATCH 3/3] liblog: allow event tags to include some punctuations event_log_tag parser complains about a period (.) in the name, we would consider such an enhancement to the tag names possible. I expect we would want to be able to support alphanumerics, underscore (_), period (.), minus (-), at (@) and comma (,) for starters as they are present in the other text log buffer tags. We introduce a local endOfTag function that is used during parsing and during android_lookupEventTagNum for submitting new tags. This function caused us to enforce const char more closely. By filtering in both places we resolve an issue that could have plagued us if garbage requests were made. Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests Bug: 31456426 Change-Id: I596b8706e843719ddac07ec40e1cd2875c214bed --- liblog/event_tag_map.cpp | 53 +++++++++++++++++++++--------------- logcat/tests/logcat_test.cpp | 2 +- 2 files changed, 32 insertions(+), 23 deletions(-) diff --git a/liblog/event_tag_map.cpp b/liblog/event_tag_map.cpp index 0b977c21e..73ed16f33 100644 --- a/liblog/event_tag_map.cpp +++ b/liblog/event_tag_map.cpp @@ -229,9 +229,16 @@ int EventTagMap::find(MapString&& tag) const { return it->second; } +// The position after the end of a valid section of the tag string, +// caller makes sure delimited appropriately. +static const char* endOfTag(const char* cp) { + while (*cp && (isalnum(*cp) || strchr("_.-@,", *cp))) ++cp; + return cp; +} + // Scan one tag line. // -// "*pData" should be pointing to the first digit in the tag number. On +// "pData" should be pointing to the first digit in the tag number. On // successful return, it will be pointing to the last character in the // tag line (i.e. the character before the start of the next line). // @@ -241,10 +248,11 @@ int EventTagMap::find(MapString&& tag) const { // data and it will outlive the call. // // Returns 0 on success, nonzero on failure. -static int scanTagLine(EventTagMap* map, char** pData, int lineNum) { - char* cp; - unsigned long val = strtoul(*pData, &cp, 10); - if (cp == *pData) { +static int scanTagLine(EventTagMap* map, const char*& pData, int lineNum) { + char* ep; + unsigned long val = strtoul(pData, &ep, 10); + const char* cp = ep; + if (cp == pData) { if (lineNum) { fprintf(stderr, OUT_TAG ": malformed tag number on line %d\n", lineNum); } @@ -273,14 +281,13 @@ static int scanTagLine(EventTagMap* map, char** pData, int lineNum) { } const char* tag = cp; - // Determine whether "c" is a valid tag char. - while (isalnum(*++cp) || (*cp == '_')) { - } + cp = endOfTag(cp); size_t tagLen = cp - tag; if (!isspace(*cp)) { if (lineNum) { - fprintf(stderr, OUT_TAG ": invalid tag chars on line %d\n", lineNum); + fprintf(stderr, OUT_TAG ": invalid tag char %c on line %d\n", *cp, + lineNum); } errno = EINVAL; return -1; @@ -311,9 +318,9 @@ static int scanTagLine(EventTagMap* map, char** pData, int lineNum) { while (*cp != '\n') ++cp; #ifdef DEBUG - fprintf(stderr, "%d: %p: %.*s\n", lineNum, tag, (int)(cp - *pData), *pData); + fprintf(stderr, "%d: %p: %.*s\n", lineNum, tag, (int)(cp - pData), pData); #endif - *pData = cp; + pData = cp; if (lineNum) { if (map->emplaceUnique(tagIndex, @@ -341,9 +348,9 @@ static const char* eventTagFiles[NUM_MAPS] = { // Parse the tags out of the file. static int parseMapLines(EventTagMap* map, size_t which) { - char* cp = static_cast(map->mapAddr[which]); + const char* cp = static_cast(map->mapAddr[which]); size_t len = map->mapLen[which]; - char* endp = cp + len; + const char* endp = cp + len; // insist on EOL at EOF; simplifies parsing and null-termination if (!len || (*(endp - 1) != '\n')) { @@ -370,7 +377,7 @@ static int parseMapLines(EventTagMap* map, size_t which) { lineStart = false; } else if (isdigit(*cp)) { // looks like a tag; scan it out - if (scanTagLine(map, &cp, lineNum) != 0) { + if (scanTagLine(map, cp, lineNum) != 0) { if (!which || (errno != EMLINK)) { return -1; } @@ -495,14 +502,13 @@ static const TagFmt* __getEventTag(EventTagMap* map, unsigned int tag) { int ret = asprintf(&buf, command_template, tag); if (ret > 0) { // Add some buffer margin for an estimate of the full return content. - char* cp; size_t size = ret - strlen(command_template) + strlen("65535\n4294967295\t?\t\t\t?\t# uid=32767\n\n\f?success?"); if (size > (size_t)ret) { - cp = static_cast(realloc(buf, size)); - if (cp) { - buf = cp; + char* np = static_cast(realloc(buf, size)); + if (np) { + buf = np; } else { size = ret; } @@ -512,10 +518,12 @@ static const TagFmt* __getEventTag(EventTagMap* map, unsigned int tag) { // Ask event log tag service for an existing entry if (__send_log_msg(buf, size) >= 0) { buf[size - 1] = '\0'; - unsigned long val = strtoul(buf, &cp, 10); // return size + char* ep; + unsigned long val = strtoul(buf, &ep, 10); // return size + const char* cp = ep; if ((buf != cp) && (val > 0) && (*cp == '\n')) { // truncation OK ++cp; - if (!scanTagLine(map, &cp, 0)) { + if (!scanTagLine(map, cp, 0)) { free(buf); return map->find(tag); } @@ -573,8 +581,9 @@ LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, LIBLOG_ABI_PUBLIC int android_lookupEventTagNum(EventTagMap* map, const char* tagname, const char* format, int prio) { - size_t len = strlen(tagname); - if (!len) { + const char* ep = endOfTag(tagname); + size_t len = ep - tagname; + if (!len || *ep) { errno = EINVAL; return -1; } diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index 33355e4f5..e487a9720 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -1677,7 +1677,7 @@ TEST(logcat, descriptive) { // Invent new entries because existing can not serve EventTagMap* map = android_openEventTagMap(nullptr); ASSERT_TRUE(nullptr != map); - static const char name[] = ___STRING(logcat) "_descriptive_monotonic"; + static const char name[] = ___STRING(logcat) ".descriptive-monotonic"; int myTag = android_lookupEventTagNum(map, name, "(new|1|s)", ANDROID_LOG_UNKNOWN); android_closeEventTagMap(map);