Merge changes I596b8706,I262c0377,Iaf2bee97 am: 030b4d1b08 am: 3447f72d43
am: fa80674a19
Change-Id: I94bad3a2c64194c2377de4277c066bbd3030f823
diff --git a/liblog/event.logtags b/liblog/event.logtags
index 301e885..0a3b650 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/event_tag_map.cpp b/liblog/event_tag_map.cpp
index 0b977c2..73ed16f 100644
--- a/liblog/event_tag_map.cpp
+++ b/liblog/event_tag_map.cpp
@@ -229,9 +229,16 @@
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 @@
// 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 @@
}
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 @@
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 @@
// Parse the tags out of the file.
static int parseMapLines(EventTagMap* map, size_t which) {
- char* cp = static_cast<char*>(map->mapAddr[which]);
+ const char* cp = static_cast<char*>(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 @@
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 @@
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<char*>(realloc(buf, size));
- if (cp) {
- buf = cp;
+ char* np = static_cast<char*>(realloc(buf, size));
+ if (np) {
+ buf = np;
} else {
size = ret;
}
@@ -512,10 +518,12 @@
// 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 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/liblog/logprint.c b/liblog/logprint.c
index 2ade7b0..b62f8b4 100644
--- a/liblog/logprint.c
+++ b/liblog/logprint.c
@@ -326,6 +326,7 @@
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 @@
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 @@
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 @@
* 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 @@
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 9f05351..efcc817 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 21868f2..e487a97 100644
--- a/logcat/tests/logcat_test.cpp
+++ b/logcat/tests/logcat_test.cpp
@@ -17,6 +17,7 @@
#include <ctype.h>
#include <dirent.h>
#include <signal.h>
+#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
@@ -31,6 +32,7 @@
#include <android-base/file.h>
#include <gtest/gtest.h>
+#include <log/event_tag_map.h>
#include <log/log.h>
#include <log/log_event_list.h>
@@ -47,6 +49,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 +82,7 @@
#undef LOG_TAG
#define LOG_TAG "inject"
RLOGE(logcat_executable ".buckets");
- sleep(1);
+ rest();
ASSERT_TRUE(NULL !=
(fp = logcat_popen(
@@ -1412,7 +1424,7 @@
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 +1462,7 @@
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 +1487,7 @@
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 +1533,12 @@
// 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 +1546,28 @@
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 +1576,8 @@
{
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 +1585,8 @@
{
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 +1598,8 @@
{
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 +1607,8 @@
{
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 +1619,48 @@
{
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,9 +1668,52 @@
{
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, ""));
}
+
+ {
+ // 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 39063a9..fa13a62 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.