liblog: logcat: logprint support -v descriptive am: 4fd0507b20 am: cacd9dc244 am: 3bcdc007c1 (0820e1e5) · Commits · e / os / android_system_core

include/log/logprint.h

+1 −0

Original line number	Diff line number	Diff line
		@@ -46,6 +46,7 @@ typedef enum {
		FORMAT_MODIFIER_EPOCH, /* Print time as seconds since Jan 1 1970 */
		FORMAT_MODIFIER_MONOTONIC, /* Print cpu time as seconds since start */
		FORMAT_MODIFIER_UID, /* Adds uid */
		FORMAT_MODIFIER_DESCRIPT, /* Adds descriptive */
		} AndroidLogPrintFormat;

		typedef struct AndroidLogFormat_t AndroidLogFormat;

liblog/logprint.c

+252 −34

Original line number	Diff line number	Diff line
		@@ -21,13 +21,13 @@
		#include <assert.h>
		#include <ctype.h>
		#include <errno.h>
		#include <inttypes.h>
		#include <pwd.h>
		#include <stdbool.h>
		#include <stdint.h>
		#include <stdio.h>
		#include <stdlib.h>
		#include <string.h>
		#include <inttypes.h>
		#include <sys/param.h>
		#include <sys/types.h>

		@@ -58,8 +58,15 @@ struct AndroidLogFormat_t {
		bool epoch_output;
		bool monotonic_output;
		bool uid_output;
		bool descriptive_output;
		};

		/*
		* API issues prevent us from exposing "descriptive" in AndroidLogFormat_t
		* during android_log_processBinaryLogBuffer(), so we break layering.
		*/
		static bool descriptive_output = false;

		/*
		* gnome-terminal color tags
		* See http://misc.flogisoft.com/bash/tip_colors_and_formatting
		@@ -209,6 +216,8 @@ LIBLOG_ABI_PUBLIC AndroidLogFormat *android_log_format_new()
		p_ret->epoch_output = false;
		p_ret->monotonic_output = android_log_clockid() == CLOCK_MONOTONIC;
		p_ret->uid_output = false;
		p_ret->descriptive_output = false;
		descriptive_output = false;

		return p_ret;
		}
		@@ -267,6 +276,10 @@ LIBLOG_ABI_PUBLIC int android_log_setPrintFormat(
		case FORMAT_MODIFIER_UID:
		p_format->uid_output = true;
		return 0;
		case FORMAT_MODIFIER_DESCRIPT:
		p_format->descriptive_output = true;
		descriptive_output = true;
		return 0;
		default:
		break;
		}
		@@ -294,6 +307,7 @@ LIBLOG_ABI_PUBLIC AndroidLogPrintFormat android_log_formatFromString(
		else if (strcmp(formatString, "threadtime") == 0) format = FORMAT_THREADTIME;
		else if (strcmp(formatString, "long") == 0) format = FORMAT_LONG;
		else if (strcmp(formatString, "color") == 0) format = FORMAT_MODIFIER_COLOR;
		else if (strcmp(formatString, "colour") == 0) format = FORMAT_MODIFIER_COLOR;
		else if (strcmp(formatString, "usec") == 0) format = FORMAT_MODIFIER_TIME_USEC;
		else if (strcmp(formatString, "printable") == 0) format = FORMAT_MODIFIER_PRINTABLE;
		else if (strcmp(formatString, "year") == 0) format = FORMAT_MODIFIER_YEAR;
		@@ -301,6 +315,7 @@ LIBLOG_ABI_PUBLIC AndroidLogPrintFormat android_log_formatFromString(
		else if (strcmp(formatString, "epoch") == 0) format = FORMAT_MODIFIER_EPOCH;
		else if (strcmp(formatString, "monotonic") == 0) format = FORMAT_MODIFIER_MONOTONIC;
		else if (strcmp(formatString, "uid") == 0) format = FORMAT_MODIFIER_UID;
		else if (strcmp(formatString, "descriptive") == 0) format = FORMAT_MODIFIER_DESCRIPT;
		else {
		extern char *tzname[2];
		static const char gmt[] = "GMT";
		@@ -566,6 +581,19 @@ static inline uint64_t get8LE(const uint8_t* src)
		return ((uint64_t) high << 32) \| (uint64_t) low;
		}

		static bool findChar(const char** cp, size_t* len, int c) {
		while (len && isspace(*cp)) {
		++*cp;
		--*len;
		}
		if (c == INT_MAX) return *len;
		if (len && (*cp == c)) {
		++*cp;
		--*len;
		return true;
		}
		return false;
		}

		/*
		* Recursively convert binary log data to printable form.
		@@ -578,27 +606,128 @@ static inline uint64_t get8LE(const uint8_t* src)
		*
		* Returns 0 on success, 1 on buffer full, -1 on failure.
		*/
		enum objectType {
		TYPE_OBJECTS = '1',
		TYPE_BYTES = '2',
		TYPE_MILLISECONDS = '3',
		TYPE_ALLOCATIONS = '4',
		TYPE_ID = '5',
		TYPE_PERCENT = '6'
		};

		static int android_log_printBinaryEvent(const unsigned char** pEventData,
		size_t* pEventDataLen, char** pOutBuf, size_t* pOutBufLen)
		size_t* pEventDataLen, char** pOutBuf, size_t* pOutBufLen,
		const char** fmtStr, size_t* fmtLen)
		{
		const unsigned char* eventData = *pEventData;
		size_t eventDataLen = *pEventDataLen;
		char* outBuf = *pOutBuf;
		char* outBufSave = outBuf;
		size_t outBufLen = *pOutBufLen;
		size_t outBufLenSave = outBufLen;
		unsigned char type;
		size_t outCount;
		int result = 0;
		const char* cp;
		size_t len;
		int64_t lval;

		if (eventDataLen < 1)
		return -1;
		type = *eventData++;
		eventDataLen--;

		cp = NULL;
		len = 0;
		if (fmtStr && fmtStr && fmtLen && fmtLen && **fmtStr) {
		cp = *fmtStr;
		len = *fmtLen;
		}
		/*
		* event.logtag format specification:
		*
		* Optionally, after the tag names can be put a description for the value(s)
		* of the tag. Description are in the format
		* (<name>\|data type[\|data unit])
		* Multiple values are separated by commas.
		*
		* The data type is a number from the following values:
		* 1: int
		* 2: long
		* 3: string
		* 4: list
		* 5: float
		*
		* The data unit is a number taken from the following list:
		* 1: Number of objects
		* 2: Number of bytes
		* 3: Number of milliseconds
		* 4: Number of allocations
		* 5: Id
		* 6: Percent
		* Default value for data of type int/long is 2 (bytes).
		*/
		if (!cp \|\| !findChar(&cp, &len, '(')) {
		len = 0;
		} else {
		char* outBufLastSpace = NULL;

		findChar(&cp, &len, INT_MAX);
		while (len && cp && (cp != '\|') && (*cp != ')')) {
		if (outBufLen <= 0) {
		/* halt output */
		goto no_room;
		}
		outBufLastSpace = isspace(*cp) ? outBuf : NULL;
		outBuf = cp;
		++outBuf;
		++cp;
		--outBufLen;
		--len;
		}
		if (outBufLastSpace) {
		outBufLen += outBuf - outBufLastSpace;
		outBuf = outBufLastSpace;
		}
		if (outBufLen <= 0) {
		/* halt output */
		goto no_room;
		}
		if (outBufSave != outBuf) {
		*outBuf = '=';
		++outBuf;
		--outBufLen;
		}

		if (findChar(&cp, &len, '\|') && findChar(&cp, &len, INT_MAX)) {
		static const unsigned char typeTable[] = {
		EVENT_TYPE_INT,
		EVENT_TYPE_LONG,
		EVENT_TYPE_STRING,
		EVENT_TYPE_LIST,
		EVENT_TYPE_FLOAT
		};

		if ((*cp >= '1') &&
		(*cp < (char)('1' + (sizeof(typeTable) / sizeof(typeTable[0])))) &&
		(type != typeTable[(size_t)(*cp - '1')])) len = 0;

		if (len) {
		++cp;
		--len;
		} else {
		/* reset the format */
		outBuf = outBufSave;
		outBufLen = outBufLenSave;
		}
		}
		}
		lval = 0;
		switch (type) {
		case EVENT_TYPE_INT:
		/* 32-bit signed int */
		{
		int ival;
		int32_t ival;

		if (eventDataLen < 4)
		return -1;
		@@ -606,27 +735,17 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData,
		eventData += 4;
		eventDataLen -= 4;

		outCount = snprintf(outBuf, outBufLen, "%d", ival);
		if (outCount < outBufLen) {
		outBuf += outCount;
		outBufLen -= outCount;
		} else {
		/* halt output */
		goto no_room;
		lval = ival;
		}
		}
		break;
		goto pr_lval;
		case EVENT_TYPE_LONG:
		/* 64-bit signed long */
		{
		uint64_t lval;

		if (eventDataLen < 8)
		return -1;
		lval = get8LE(eventData);
		eventData += 8;
		eventDataLen -= 8;

		pr_lval:
		outCount = snprintf(outBuf, outBufLen, "%" PRId64, lval);
		if (outCount < outBufLen) {
		outBuf += outCount;
		@@ -635,7 +754,6 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData,
		/* halt output */
		goto no_room;
		}
		}
		break;
		case EVENT_TYPE_FLOAT:
		/* float */
		@@ -674,6 +792,11 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData,
		if (eventDataLen < strLen)
		return -1;

		if (cp && (strLen == 0)) {
		/* reset the format if no content */
		outBuf = outBufSave;
		outBufLen = outBufLenSave;
		}
		if (strLen < outBufLen) {
		memcpy(outBuf, eventData, strLen);
		outBuf += strLen;
		@@ -710,7 +833,7 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData,

		for (i = 0; i < count; i++) {
		result = android_log_printBinaryEvent(&eventData, &eventDataLen,
		&outBuf, &outBufLen);
		&outBuf, &outBufLen, fmtStr, fmtLen);
		if (result != 0)
		goto bail;

		@@ -736,12 +859,90 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData,
		fprintf(stderr, "Unknown binary event type %d\n", type);
		return -1;
		}
		if (cp && len) {
		if (findChar(&cp, &len, '\|') && findChar(&cp, &len, INT_MAX)) {
		switch (*cp) {
		case TYPE_OBJECTS:
		outCount = 0;
		/* outCount = snprintf(outBuf, outBufLen, " objects"); */
		break;
		case TYPE_BYTES:
		if ((lval != 0) && ((lval % 1024) == 0)) {
		/* repaint with multiplier */
		static const char suffixTable[] = { 'K', 'M', 'G', 'T' };
		size_t idx = 0;
		outBuf -= outCount;
		outBufLen += outCount;
		do {
		lval /= 1024;
		if ((lval % 1024) != 0) break;
		} while (++idx < ((sizeof(suffixTable) /
		sizeof(suffixTable[0])) - 1));
		outCount = snprintf(outBuf, outBufLen,
		"%" PRId64 "%cB",
		lval, suffixTable[idx]);
		} else {
		outCount = snprintf(outBuf, outBufLen, "B");
		}
		break;
		case TYPE_MILLISECONDS:
		if (((lval <= -1000) \|\| (1000 <= lval)) &&
		(outBufLen \|\| (outBuf[-1] == '0'))) {
		/* repaint as (fractional) seconds, possibly saving space */
		if (outBufLen) outBuf[0] = outBuf[-1];
		outBuf[-1] = outBuf[-2];
		outBuf[-2] = outBuf[-3];
		outBuf[-3] = '.';
		while ((outBufLen == 0) \|\| (*outBuf == '0')) {
		--outBuf;
		++outBufLen;
		}
		if (*outBuf != '.') {
		++outBuf;
		--outBufLen;
		}
		outCount = snprintf(outBuf, outBufLen, "s");
		} else {
		outCount = snprintf(outBuf, outBufLen, "ms");
		}
		break;
		case TYPE_ALLOCATIONS:
		outCount = 0;
		/* outCount = snprintf(outBuf, outBufLen, " allocations"); */
		break;
		case TYPE_ID:
		outCount = 0;
		break;
		case TYPE_PERCENT:
		outCount = snprintf(outBuf, outBufLen, "%%");
		break;
		default: /* ? */
		outCount = 0;
		break;
		}
		++cp;
		--len;
		if (outCount < outBufLen) {
		outBuf += outCount;
		outBufLen -= outCount;
		} else if (outCount) {
		/* halt output */
		goto no_room;
		}
		}
		if (!findChar(&cp, &len, ')')) len = 0;
		if (!findChar(&cp, &len, ',')) len = 0;
		}

		bail:
		*pEventData = eventData;
		*pEventDataLen = eventDataLen;
		*pOutBuf = outBuf;
		*pOutBufLen = outBufLen;
		if (cp) {
		*fmtStr = cp;
		*fmtLen = len;
		}
		return result;

		no_room:
		@@ -764,7 +965,7 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer(
		char *messageBuf, int messageBufLen)
		{
		size_t inCount;
		unsigned int tagIndex;
		uint32_t tagIndex;
		const unsigned char* eventData;

		entry->tv_sec = buf->sec;
		@@ -817,7 +1018,7 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer(
		if (entry->tag == NULL) {
		size_t tagLen;

		tagLen = snprintf(messageBuf, messageBufLen, "[%d]", tagIndex);
		tagLen = snprintf(messageBuf, messageBufLen, "[%" PRIu32 "]", tagIndex);
		if (tagLen >= (size_t)messageBufLen) {
		tagLen = messageBufLen - 1;
		}
		@@ -833,8 +1034,25 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer(
		char* outBuf = messageBuf;
		size_t outRemaining = messageBufLen - 1; /* leave one for nul byte */
		int result;
		const char* fmtStr = NULL;
		size_t fmtLen = 0;
		if (descriptive_output && map) {
		fmtStr = android_lookupEventFormat_len(map, &fmtLen, tagIndex);
		}
		result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
		&outRemaining, &fmtStr, &fmtLen);
		if ((result == 1) && fmtStr) {
		/* We overflowed :-(, let's repaint the line w/o format dressings */
		eventData = (const unsigned char*)buf->msg;
		if (buf2->hdr_size) {
		eventData = ((unsigned char *)buf2) + buf2->hdr_size;
		}
		eventData += 4;
		outBuf = messageBuf;
		outRemaining = messageBufLen - 1;
		result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
		&outRemaining);
		&outRemaining, NULL, NULL);
		}
		if (result < 0) {
		fprintf(stderr, "Binary log entry conversion failed\n");
		return -1;

logcat/logcat.cpp

+106 −41

File changed.

Preview size limit exceeded, changes collapsed.

logcat/tests/logcat_test.cpp

+161 −0

Original line number	Diff line number	Diff line
		@@ -25,6 +25,7 @@
		#include <sys/wait.h>

		#include <memory>
		#include <string>

		#include <gtest/gtest.h>
		#include <log/log.h>
		@@ -1235,3 +1236,163 @@ TEST(logcat, maxcount) {

		ASSERT_EQ(3, count);
		}

		static bool End_to_End(const char* tag, const char* fmt, ...)
		#if defined(__GNUC__)
		__attribute__((__format__(printf, 2, 3)))
		#endif
		;

		static bool End_to_End(const char* tag, const char* fmt, ...) {
		FILE *fp = popen("logcat -v brief -b events -v descriptive -t 100 2>/dev/null", "r");
		if (!fp) return false;

		char buffer[BIG_BUFFER];
		va_list ap;

		va_start(ap, fmt);
		vsnprintf(buffer, sizeof(buffer), fmt, ap);
		va_end(ap);

		char *str = NULL;
		asprintf(&str, "I/%s ( %%d): %s%%c", tag, buffer);
		std::string expect(str);
		free(str);

		int count = 0;
		pid_t pid = getpid();
		std::string lastMatch;
		while (fgets(buffer, sizeof(buffer), fp)) {
		char newline;
		int p;
		int ret = sscanf(buffer, expect.c_str(), &p, &newline);
		if ((2 == ret) && (p == pid) && (newline == '\n')) ++count;
		else if ((1 == ret) && (p == pid) && (count == 0)) lastMatch = buffer;
		}

		pclose(fp);

		if ((count == 0) && (lastMatch.length() > 0)) {
		// Help us pinpoint where things went wrong ...
		fprintf(stderr, "Closest match for\n %s\n is\n %s",
		expect.c_str(), lastMatch.c_str());
		}

		return count == 1;
		}

		TEST(logcat, descriptive) {
		struct tag {
		uint32_t tagNo;
		const char* tagStr;
		};

		{
		static const struct tag hhgtg = { 42, "answer" };
		android_log_event_context ctx(hhgtg.tagNo);
		static const char theAnswer[] = "what is five by seven";
		ctx << theAnswer;
		ctx.write();
		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";
		{
		android_log_event_context ctx(sync.tagNo);
		ctx << id << (int32_t)42 << (int32_t)-1 << (int32_t)0;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr,
		"[id=%s,event=42,source=-1,account=0]",
		id));
		}

		// Partial match to description
		{
		android_log_event_context ctx(sync.tagNo);
		ctx << id << (int32_t)43 << (int64_t)-1 << (int32_t)0;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr,
		"[id=%s,event=43,-1,0]",
		id));
		}

		// Negative Test of End_to_End, ensure it is working
		{
		android_log_event_context ctx(sync.tagNo);
		ctx << id << (int32_t)44 << (int32_t)-1 << (int64_t)0;
		ctx.write();
		fprintf(stderr, "Expect a \"Closest match\" message\n");
		EXPECT_FALSE(End_to_End(sync.tagStr,
		"[id=%s,event=44,source=-1,account=0]",
		id));
		}
		}

		{
		static const struct tag sync = { 2747, "contacts_aggregation" };
		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint64_t)30 << (int32_t)2;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr,
		"[aggregation time=30ms,count=2]"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint64_t)31570 << (int32_t)911;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr,
		"[aggregation time=31.57s,count=911]"));
		}
		}

		{
		static const struct tag sync = { 75000, "sqlite_mem_alarm_current" };
		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)512;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=512B"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)3072;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=3KB"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)2097152;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=2MB"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)2097153;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=2097153B"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)1073741824;
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=1GB"));
		}

		{
		android_log_event_context ctx(sync.tagNo);
		ctx << (uint32_t)3221225472; // 3MB, but on purpose overflowed
		ctx.write();
		EXPECT_TRUE(End_to_End(sync.tagStr, "current=-1GB"));
		}
		}

		}