Merge "logd: regression in handling watermark boundary." into oc-dev
am: 79af3c6d6a
Change-Id: Ib5c8303d796958136ee586bbcd63cbbe33e12e59
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 231f4d9..5fc7e35 100644
--- a/liblog/event_tag_map.cpp
+++ b/liblog/event_tag_map.cpp
@@ -230,9 +230,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).
//
@@ -242,10 +249,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);
}
@@ -274,14 +282,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;
@@ -312,9 +319,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,
@@ -342,9 +349,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')) {
@@ -371,7 +378,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;
}
@@ -446,7 +453,7 @@
mmap(NULL, end[which], which ? PROT_READ : PROT_READ | PROT_WRITE,
which ? MAP_SHARED : MAP_PRIVATE, fd[which], 0);
save_errno = errno;
- close(fd[which]);
+ close(fd[which]); /* fd DONE */
fd[which] = -1;
if ((newTagMap->mapAddr[which] != MAP_FAILED) &&
(newTagMap->mapAddr[which] != NULL)) {
@@ -466,6 +473,7 @@
delete newTagMap;
return NULL;
}
+ /* See 'fd DONE' comments above and below, no need to clean up here */
}
return newTagMap;
@@ -474,7 +482,7 @@
save_errno = EINVAL;
delete newTagMap;
fail_close:
- for (which = 0; which < NUM_MAPS; ++which) close(fd[which]);
+ for (which = 0; which < NUM_MAPS; ++which) close(fd[which]); /* fd DONE */
fail_errno:
errno = save_errno;
return NULL;
@@ -495,14 +503,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 +519,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 +582,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/include/log/log_event_list.h b/liblog/include/log/log_event_list.h
index 55953fc..057be5d 100644
--- a/liblog/include/log/log_event_list.h
+++ b/liblog/include/log/log_event_list.h
@@ -17,6 +17,7 @@
#ifndef _LIBS_LOG_EVENT_LIST_H
#define _LIBS_LOG_EVENT_LIST_H
+#include <errno.h>
#include <stdint.h>
#if (defined(__cplusplus) && defined(_USING_LIBCXX))
@@ -148,6 +149,7 @@
return ctx;
}
+ /* return errors or transmit status */
int status() const {
return ret;
}
@@ -209,14 +211,16 @@
}
int write(log_id_t id = LOG_ID_EVENTS) {
+ /* facilitate -EBUSY retry */
+ if ((ret == -EBUSY) || (ret > 0)) ret = 0;
int retval = android_log_write_list(ctx, id);
- if (retval < 0) ret = retval;
+ /* existing errors trump transmission errors */
+ if (!ret) ret = retval;
return ret;
}
int operator<<(log_id_t id) {
- int retval = android_log_write_list(ctx, id);
- if (retval < 0) ret = retval;
+ write(id);
android_log_destroy(&ctx);
return ret;
}
diff --git a/liblog/include/log/log_time.h b/liblog/include/log/log_time.h
index 5f70f7d..9ece0b3 100644
--- a/liblog/include/log/log_time.h
+++ b/liblog/include/log/log_time.h
@@ -41,13 +41,12 @@
static const uint32_t tv_sec_max = 0xFFFFFFFFUL;
static const uint32_t tv_nsec_max = 999999999UL;
- log_time(const timespec& T) {
- tv_sec = static_cast<uint32_t>(T.tv_sec);
- tv_nsec = static_cast<uint32_t>(T.tv_nsec);
+ log_time(const timespec& T)
+ : tv_sec(static_cast<uint32_t>(T.tv_sec)),
+ tv_nsec(static_cast<uint32_t>(T.tv_nsec)) {
}
- log_time(uint32_t sec, uint32_t nsec) {
- tv_sec = sec;
- tv_nsec = nsec;
+ explicit log_time(uint32_t sec, uint32_t nsec = 0)
+ : tv_sec(sec), tv_nsec(nsec) {
}
#ifdef _SYSTEM_CORE_INCLUDE_PRIVATE_ANDROID_LOGGER_H_
#define __struct_log_time_private_defined
@@ -56,14 +55,14 @@
log_time() {
}
#ifdef __linux__
- log_time(clockid_t id) {
+ explicit log_time(clockid_t id) {
timespec T;
clock_gettime(id, &T);
tv_sec = static_cast<uint32_t>(T.tv_sec);
tv_nsec = static_cast<uint32_t>(T.tv_nsec);
}
#endif
- log_time(const char* T) {
+ explicit log_time(const char* T) {
const uint8_t* c = reinterpret_cast<const uint8_t*>(T);
tv_sec = c[0] | (static_cast<uint32_t>(c[1]) << 8) |
(static_cast<uint32_t>(c[2]) << 16) |
diff --git a/liblog/logger_write.c b/liblog/logger_write.c
index d322c0f..84feb20 100644
--- a/liblog/logger_write.c
+++ b/liblog/logger_write.c
@@ -410,16 +410,46 @@
if (!tag) tag = "";
/* XXX: This needs to go! */
- if ((bufID != LOG_ID_RADIO) &&
- (!strcmp(tag, "HTC_RIL") ||
- !strncmp(tag, "RIL", 3) || /* Any log tag with "RIL" as the prefix */
- !strncmp(tag, "IMS", 3) || /* Any log tag with "IMS" as the prefix */
- !strcmp(tag, "AT") || !strcmp(tag, "GSM") || !strcmp(tag, "STK") ||
- !strcmp(tag, "CDMA") || !strcmp(tag, "PHONE") || !strcmp(tag, "SMS"))) {
- bufID = LOG_ID_RADIO;
- /* Inform third party apps/ril/radio.. to use Rlog or RLOG */
- snprintf(tmp_tag, sizeof(tmp_tag), "use-Rlog/RLOG-%s", tag);
- tag = tmp_tag;
+ if (bufID != LOG_ID_RADIO) {
+ switch (tag[0]) {
+ case 'H':
+ if (strcmp(tag + 1, "HTC_RIL" + 1)) break;
+ goto inform;
+ case 'R':
+ /* Any log tag with "RIL" as the prefix */
+ if (strncmp(tag + 1, "RIL" + 1, strlen("RIL") - 1)) break;
+ goto inform;
+ case 'Q':
+ /* Any log tag with "QC_RIL" as the prefix */
+ if (strncmp(tag + 1, "QC_RIL" + 1, strlen("QC_RIL") - 1)) break;
+ goto inform;
+ case 'I':
+ /* Any log tag with "IMS" as the prefix */
+ if (strncmp(tag + 1, "IMS" + 1, strlen("IMS") - 1)) break;
+ goto inform;
+ case 'A':
+ if (strcmp(tag + 1, "AT" + 1)) break;
+ goto inform;
+ case 'G':
+ if (strcmp(tag + 1, "GSM" + 1)) break;
+ goto inform;
+ case 'S':
+ if (strcmp(tag + 1, "STK" + 1) && strcmp(tag + 1, "SMS" + 1)) break;
+ goto inform;
+ case 'C':
+ if (strcmp(tag + 1, "CDMA" + 1)) break;
+ goto inform;
+ case 'P':
+ if (strcmp(tag + 1, "PHONE" + 1)) break;
+ /* FALLTHRU */
+ inform:
+ bufID = LOG_ID_RADIO;
+ snprintf(tmp_tag, sizeof(tmp_tag), "use-Rlog/RLOG-%s", tag);
+ tag = tmp_tag;
+ /* FALLTHRU */
+ default:
+ break;
+ }
}
#if __BIONIC__
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/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp
index 3f79552..c4bf959 100644
--- a/liblog/tests/liblog_benchmark.cpp
+++ b/liblog/tests/liblog_benchmark.cpp
@@ -527,11 +527,13 @@
/*
* Measure the time it takes to submit the android event logging call
* using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming())
- * under light load. Expect this to be a dozen or so syscall periods (40us)
+ * under light load. Expect this to be a long path to logger to convert the
+ * unknown tag (0) into a tagname (less than 200us).
*/
static void BM_log_event_overhead(int iters) {
for (unsigned long long i = 0; i < (unsigned)iters; ++i) {
StartBenchmarkTiming();
+ // log tag number 0 is not known, nor shall it ever be known
__android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i));
StopBenchmarkTiming();
logd_yield();
@@ -539,6 +541,28 @@
}
BENCHMARK(BM_log_event_overhead);
+/*
+ * Measure the time it takes to submit the android event logging call
+ * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming())
+ * under light load with a known logtag. Expect this to be a dozen or so
+ * syscall periods (less than 40us)
+ */
+static void BM_log_event_overhead_42(int iters) {
+ for (unsigned long long i = 0; i < (unsigned)iters; ++i) {
+ StartBenchmarkTiming();
+ // In system/core/logcat/event.logtags:
+ // # These are used for testing, do not modify without updating
+ // # tests/framework-tests/src/android/util/EventLogFunctionalTest.java.
+ // # system/core/liblog/tests/liblog_benchmark.cpp
+ // # system/core/liblog/tests/liblog_test.cpp
+ // 42 answer (to life the universe etc|3)
+ __android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i));
+ StopBenchmarkTiming();
+ logd_yield();
+ }
+}
+BENCHMARK(BM_log_event_overhead_42);
+
static void BM_log_event_overhead_null(int iters) {
set_log_null();
BM_log_event_overhead(iters);
diff --git a/logcat/event.logtags b/logcat/event.logtags
index 909f8e2..efcc817 100644
--- a/logcat/event.logtags
+++ b/logcat/event.logtags
@@ -30,12 +30,15 @@
# 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.
# These are used for testing, do not modify without updating
# tests/framework-tests/src/android/util/EventLogFunctionalTest.java.
+# system/core/liblog/tests/liblog_benchmark.cpp
+# system/core/liblog/tests/liblog_test.cpp
42 answer (to life the universe etc|3)
314 pi
2718 e
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/LogBuffer.cpp b/logd/LogBuffer.cpp
index 1eda15d..4aa2c9f 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -1120,9 +1120,22 @@
log_time max = start;
+ LogBufferElement* lastElement = nullptr; // iterator corruption paranoia
+ static const size_t maxSkip = 4194304; // maximum entries to skip
+ size_t skip = maxSkip;
for (; it != mLogElements.end(); ++it) {
LogBufferElement* element = *it;
+ if (!--skip) {
+ android::prdebug("reader.per: too many elements skipped");
+ break;
+ }
+ if (element == lastElement) {
+ android::prdebug("reader.per: identical elements");
+ break;
+ }
+ lastElement = element;
+
if (!privileged && (element->getUid() != uid)) {
continue;
}
@@ -1167,6 +1180,7 @@
return max;
}
+ skip = maxSkip;
pthread_mutex_lock(&mLogElementsLock);
}
pthread_mutex_unlock(&mLogElementsLock);
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index cc30f77..d3167ad 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -248,18 +248,38 @@
std::string(isprune ? "NUM" : ""));
}
+// Helper to truncate name, if too long, and add name dressings
+static void formatTmp(const LogStatistics& stat, const char* nameTmp, uid_t uid,
+ std::string& name, std::string& size, size_t nameLen) {
+ const char* allocNameTmp = nullptr;
+ if (!nameTmp) nameTmp = allocNameTmp = stat.uidToName(uid);
+ if (nameTmp) {
+ size_t lenSpace = std::max(nameLen - name.length(), (size_t)1);
+ size_t len = EntryBaseConstants::total_len -
+ EntryBaseConstants::pruned_len - size.length() -
+ name.length() - lenSpace - 2;
+ size_t lenNameTmp = strlen(nameTmp);
+ while ((len < lenNameTmp) && (lenSpace > 1)) {
+ ++len;
+ --lenSpace;
+ }
+ name += android::base::StringPrintf("%*s", (int)lenSpace, "");
+ if (len < lenNameTmp) {
+ name += "...";
+ nameTmp += lenNameTmp - std::max(len - 3, (size_t)1);
+ }
+ name += nameTmp;
+ free(const_cast<char*>(allocNameTmp));
+ }
+}
+
std::string UidEntry::format(const LogStatistics& stat, log_id_t id) const {
uid_t uid = getUid();
std::string name = android::base::StringPrintf("%u", uid);
- const char* nameTmp = stat.uidToName(uid);
- if (nameTmp) {
- name += android::base::StringPrintf(
- "%*s%s", (int)std::max(6 - name.length(), (size_t)1), "", nameTmp);
- free(const_cast<char*>(nameTmp));
- }
-
std::string size = android::base::StringPrintf("%zu", getSizes());
+ formatTmp(stat, nullptr, uid, name, size, 6);
+
std::string pruned = "";
if (worstUidEnabledForLogid(id)) {
size_t totalDropped = 0;
@@ -366,18 +386,10 @@
uid_t uid = getUid();
pid_t pid = getPid();
std::string name = android::base::StringPrintf("%5u/%u", pid, uid);
- const char* nameTmp = getName();
- if (nameTmp) {
- name += android::base::StringPrintf(
- "%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", nameTmp);
- } else if ((nameTmp = stat.uidToName(uid))) {
- name += android::base::StringPrintf(
- "%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", nameTmp);
- free(const_cast<char*>(nameTmp));
- }
-
std::string size = android::base::StringPrintf("%zu", getSizes());
+ formatTmp(stat, getName(), uid, name, size, 12);
+
std::string pruned = "";
size_t dropped = getDropped();
if (dropped) {
@@ -398,21 +410,10 @@
log_id_t /* id */) const {
uid_t uid = getUid();
std::string name = android::base::StringPrintf("%5u/%u", getTid(), uid);
- const char* nameTmp = getName();
- if (nameTmp) {
- name += android::base::StringPrintf(
- "%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", nameTmp);
- } else if ((nameTmp = stat.uidToName(uid))) {
- // if we do not have a PID name, lets punt to try UID name?
- name += android::base::StringPrintf(
- "%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", nameTmp);
- free(const_cast<char*>(nameTmp));
- // We tried, better to not have a name at all, we still
- // have TID/UID by number to report in any case.
- }
-
std::string size = android::base::StringPrintf("%zu", getSizes());
+ formatTmp(stat, getName(), uid, name, size, 12);
+
std::string pruned = "";
size_t dropped = getDropped();
if (dropped) {
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.
diff --git a/logd/main.cpp b/logd/main.cpp
index 946485b..18029eb 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -407,6 +407,11 @@
// logging plugins like auditd and restart control. Additional
// transitory per-client threads are created for each reader.
int main(int argc, char* argv[]) {
+ // logd is written under the assumption that the timezone is UTC.
+ // If TZ is not set, persist.sys.timezone is looked up in some time utility
+ // libc functions, including mktime. It confuses the logd time handling,
+ // so here explicitly set TZ to UTC, which overrides the property.
+ setenv("TZ", "UTC", 1);
// issue reinit command. KISS argument parsing.
if ((argc > 1) && argv[1] && !strcmp(argv[1], "--reinit")) {
return issueReinit();
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index ddff393..a1d154a 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -426,7 +426,7 @@
" BM_log_maximum_retry"
" BM_log_maximum"
" BM_clock_overhead"
- " BM_log_overhead"
+ " BM_log_print_overhead"
" BM_log_latency"
" BM_log_delay",
"r")));
@@ -434,13 +434,13 @@
char buffer[5120];
static const char* benchmarks[] = {
- "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ",
- "BM_log_overhead ", "BM_log_latency ", "BM_log_delay "
+ "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ",
+ "BM_log_print_overhead ", "BM_log_latency ", "BM_log_delay "
};
static const unsigned int log_maximum_retry = 0;
static const unsigned int log_maximum = 1;
static const unsigned int clock_overhead = 2;
- static const unsigned int log_overhead = 3;
+ static const unsigned int log_print_overhead = 3;
static const unsigned int log_latency = 4;
static const unsigned int log_delay = 5;
@@ -469,21 +469,23 @@
}
EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user
+ EXPECT_NE(0UL, ns[log_maximum_retry]); // failure to parse
EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user
+ EXPECT_NE(0UL, ns[log_maximum]); // failure to parse
EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
+ EXPECT_NE(0UL, ns[clock_overhead]); // failure to parse
- EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user
+ EXPECT_GE(250000UL, ns[log_print_overhead]); // 126886 user
+ EXPECT_NE(0UL, ns[log_print_overhead]); // failure to parse
EXPECT_GE(10000000UL,
ns[log_latency]); // 1453559 user space (background cgroup)
+ EXPECT_NE(0UL, ns[log_latency]); // failure to parse
EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
-
- for (unsigned i = 0; i < arraysize(ns); ++i) {
- EXPECT_NE(0UL, ns[i]);
- }
+ EXPECT_NE(0UL, ns[log_delay]); // failure to parse
alloc_statistics(&buf, &len);
@@ -668,8 +670,12 @@
while (--i) {
int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
SOCK_SEQPACKET);
- EXPECT_LT(0, fd);
- if (fd < 0) _exit(fd);
+ int save_errno = errno;
+ if (fd < 0) {
+ fprintf(stderr, "failed to open /dev/socket/logdr %s\n",
+ strerror(save_errno));
+ _exit(fd);
+ }
std::string ask = android::base::StringPrintf(
"dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32
@@ -721,8 +727,12 @@
// active _or_ inactive during the test.
if (content_timeout) {
log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
- EXPECT_FALSE(msg < now);
- if (msg < now) _exit(-1);
+ if (msg < now) {
+ fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec,
+ msg_timeout.entry.nsec, (unsigned)now.tv_sec,
+ (unsigned)now.tv_nsec);
+ _exit(-1);
+ }
if (msg > now) {
now = msg;
now.tv_sec += 30;
@@ -997,16 +1007,18 @@
}
// We may have DAC, but let's not have MAC
- if (setcon("u:object_r:shell:s0") < 0) {
+ if ((setcon("u:object_r:shell:s0") < 0) && (setcon("u:r:shell:s0") < 0)) {
int save_errno = errno;
security_context_t context;
getcon(&context);
- fprintf(stderr, "setcon(\"u:r:shell:s0\") failed @\"%s\" %s\n", context,
- strerror(save_errno));
- freecon(context);
- _exit(-1);
- // NOTREACHED
- return 0;
+ if (strcmp(context, "u:r:shell:s0")) {
+ fprintf(stderr, "setcon(\"u:r:shell:s0\") failed @\"%s\" %s\n",
+ context, strerror(save_errno));
+ freecon(context);
+ _exit(-1);
+ // NOTREACHED
+ return 0;
+ }
}
// The key here is we are root, but we are in u:r:shell:s0,