From 4fd0507b20d5afcc7b67ec355dcd89df62e62fc6 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 18 Oct 2016 11:30:11 -0700 Subject: [PATCH] liblog: logcat: logprint support -v descriptive Expand logprint feature to pull out the log tag description fields, parse them and merge into the logging content. Add -v descriptive, -v colour(british, hidden) and -v help. Also added a unit test for the descriptive format borrowing from event tags that have been unchanged since 2009. Had to add -v help because we have too many undocumented formats and format adverbs. Test: gTest logcat-unit-tests --gtest_filter=logcat.descriptive Bug: 31456426 Change-Id: I93a1c003b7a3f4c332544946fdedb7277919cec3 --- include/log/logprint.h | 1 + liblog/logprint.c | 286 ++++++++++++++++++++++++++++++----- logcat/logcat.cpp | 147 +++++++++++++----- logcat/tests/logcat_test.cpp | 161 ++++++++++++++++++++ 4 files changed, 520 insertions(+), 75 deletions(-) diff --git a/include/log/logprint.h b/include/log/logprint.h index 493f9f856..3509e7f51 100644 --- a/include/log/logprint.h +++ b/include/log/logprint.h @@ -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; diff --git a/liblog/logprint.c b/liblog/logprint.c index 1ff71363c..fb942a1a5 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -21,13 +21,13 @@ #include #include #include +#include #include #include #include #include #include #include -#include #include #include @@ -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 + * (|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,35 +735,24 @@ 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; - - outCount = snprintf(outBuf, outBufLen, "%" PRId64, lval); - if (outCount < outBufLen) { - outBuf += outCount; - outBufLen -= outCount; - } else { - /* halt output */ - goto no_room; - } + 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; + outBufLen -= outCount; + } else { + /* halt output */ + goto no_room; } break; case EVENT_TYPE_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; } @@ -831,10 +1032,27 @@ LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer( * Format the event log data into the buffer. */ char* outBuf = messageBuf; - size_t outRemaining = messageBufLen-1; /* leave one for nul byte */ + 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); + &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, NULL, NULL); + } if (result < 0) { fprintf(stderr, "Binary log entry conversion failed\n"); return -1; diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index f08a6cdac..d0c693d31 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -82,8 +82,14 @@ static size_t g_maxCount; static size_t g_printCount; static bool g_printItAnyways; +enum helpType { + HELP_FALSE, + HELP_TRUE, + HELP_FORMAT +}; + // if showHelp is set, newline required in fmt statement to transition to usage -__noreturn static void logcat_panic(bool showHelp, const char *fmt, ...) __printflike(2,3); +__noreturn static void logcat_panic(enum helpType showHelp, const char *fmt, ...) __printflike(2,3); static int openLogFile (const char *pathname) { @@ -133,7 +139,7 @@ static void rotateLogs() g_outFD = openLogFile(g_outputFileName); if (g_outFD < 0) { - logcat_panic(false, "couldn't open output file"); + logcat_panic(HELP_FALSE, "couldn't open output file"); } g_outByteCount = 0; @@ -196,7 +202,7 @@ static void processBuffer(log_device_t* dev, struct log_msg *buf) bytesWritten = android_log_printLogLine(g_logformat, g_outFD, &entry); if (bytesWritten < 0) { - logcat_panic(false, "output error"); + logcat_panic(HELP_FALSE, "output error"); } } } @@ -210,7 +216,6 @@ static void processBuffer(log_device_t* dev, struct log_msg *buf) } error: - //fprintf (stderr, "Error processing record\n"); return; } @@ -222,7 +227,7 @@ static void maybePrintStart(log_device_t* dev, bool printDividers) { dev->printed ? "switch to" : "beginning of", dev->device); if (write(g_outFD, buf, strlen(buf)) < 0) { - logcat_panic(false, "output error"); + logcat_panic(HELP_FALSE, "output error"); } } dev->printed = true; @@ -256,18 +261,18 @@ static void setupOutputAndSchedulingPolicy(bool blocking) { g_outFD = openLogFile (g_outputFileName); if (g_outFD < 0) { - logcat_panic(false, "couldn't open output file"); + logcat_panic(HELP_FALSE, "couldn't open output file"); } struct stat statbuf; if (fstat(g_outFD, &statbuf) == -1) { close(g_outFD); - logcat_panic(false, "couldn't get output file stat\n"); + logcat_panic(HELP_FALSE, "couldn't get output file stat\n"); } if ((size_t) statbuf.st_size > SIZE_MAX || statbuf.st_size < 0) { close(g_outFD); - logcat_panic(false, "invalid output file stat\n"); + logcat_panic(HELP_FALSE, "invalid output file stat\n"); } g_outByteCount = statbuf.st_size; @@ -288,9 +293,10 @@ static void show_help(const char *cmd) " the fileset and continue\n" " -v , --format=\n" " Sets log print format verb and adverbs, where is:\n" - " brief long process raw tag thread threadtime time\n" + " brief help long process raw tag thread threadtime time\n" " and individually flagged modifying adverbs can be added:\n" - " color epoch monotonic printable uid usec UTC year zone\n" + " color descriptive epoch monotonic printable uid\n" + " usec UTC year zone\n" " -D, --dividers Print dividers between each log buffer\n" " -c, --clear Clear (flush) the entire log and exit\n" " if Log to File specified, clear fileset instead\n" @@ -356,6 +362,40 @@ static void show_help(const char *cmd) "or defaults to \"threadtime\"\n\n"); } +static void show_format_help() +{ + fprintf(stderr, + "-v , --format= options:\n" + " Sets log print format verb and adverbs, where is:\n" + " brief long process raw tag thread threadtime time\n" + " and individually flagged modifying adverbs can be added:\n" + " color descriptive epoch monotonic printable uid usec UTC year zone\n" + "\nSingle format verbs:\n" + " brief — Display priority/tag and PID of the process issuing the message.\n" + " long — Display all metadata fields, separate messages with blank lines.\n" + " process — Display PID only.\n" + " raw — Display the raw log message, with no other metadata fields.\n" + " tag — Display the priority/tag only.\n" + " threadtime — Display the date, invocation time, priority, tag, and the PID\n" + " and TID of the thread issuing the message. (the default format).\n" + " time — Display the date, invocation time, priority/tag, and PID of the\n" + " process issuing the message.\n" + "\nAdverb modifiers can be used in combination:\n" + " color — Display in highlighted color to match priority. i.e. \x1B[38;5;231mVERBOSE\n" + " \x1B[38;5;75mDEBUG \x1B[38;5;40mINFO \x1B[38;5;166mWARNING \x1B[38;5;196mERROR FATAL\x1B[0m\n" + " descriptive — events logs only, descriptions from event-log-tags database.\n" + " epoch — Display time as seconds since Jan 1 1970.\n" + " monotonic — Display time as cpu seconds since last boot.\n" + " printable — Ensure that any binary logging content is escaped.\n" + " uid — If permitted, display the UID or Android ID of logged process.\n" + " usec — Display time down the microsecond precision.\n" + " UTC — Display time as UTC.\n" + " year — Add the year to the displayed time.\n" + " zone — Add the local timezone to the displayed time.\n" + " \"\" — Print using this public named timezone (experimental).\n\n" + ); +} + static int setLogFormat(const char * formatString) { static AndroidLogPrintFormat format; @@ -418,15 +458,23 @@ static bool getSizeTArg(const char *ptr, size_t *val, size_t min = 0, return true; } -static void logcat_panic(bool showHelp, const char *fmt, ...) +static void logcat_panic(enum helpType showHelp, const char *fmt, ...) { va_list args; va_start(args, fmt); vfprintf(stderr, fmt, args); va_end(args); - if (showHelp) { + switch (showHelp) { + case HELP_TRUE: show_help(getprogname()); + break; + case HELP_FORMAT: + show_format_help(); + break; + case HELP_FALSE: + default: + break; } exit(EXIT_FAILURE); @@ -616,7 +664,7 @@ int main(int argc, char **argv) if (long_options[option_index].name == pid_str) { // ToDo: determine runtime PID_MAX? if (!getSizeTArg(optarg, &pid, 1)) { - logcat_panic(true, "%s %s out of range\n", + logcat_panic(HELP_TRUE, "%s %s out of range\n", long_options[option_index].name, optarg); } break; @@ -628,7 +676,7 @@ int main(int argc, char **argv) // ToDo: implement API that supports setting a wrap timeout size_t dummy = ANDROID_LOG_WRAP_DEFAULT_TIMEOUT; if (optarg && !getSizeTArg(optarg, &dummy, 1)) { - logcat_panic(true, "%s %s out of range\n", + logcat_panic(HELP_TRUE, "%s %s out of range\n", long_options[option_index].name, optarg); } if (dummy != ANDROID_LOG_WRAP_DEFAULT_TIMEOUT) { @@ -675,7 +723,8 @@ int main(int argc, char **argv) if (strspn(optarg, "0123456789") != strlen(optarg)) { char *cp = parseTime(tail_time, optarg); if (!cp) { - logcat_panic(false, "-%c \"%s\" not in time format\n", + logcat_panic(HELP_FALSE, + "-%c \"%s\" not in time format\n", ret, optarg); } if (*cp) { @@ -707,7 +756,7 @@ int main(int argc, char **argv) case 'm': { char *end = NULL; if (!getSizeTArg(optarg, &g_maxCount)) { - logcat_panic(false, "-%c \"%s\" isn't an " + logcat_panic(HELP_FALSE, "-%c \"%s\" isn't an " "integer greater than zero\n", ret, optarg); } } @@ -780,7 +829,8 @@ int main(int argc, char **argv) const char *name = android_log_id_to_name(log_id); if (strcmp(name, optarg) != 0) { - logcat_panic(true, "unknown buffer %s\n", optarg); + logcat_panic(HELP_TRUE, + "unknown buffer %s\n", optarg); } idMask |= (1 << log_id); } @@ -841,20 +891,27 @@ int main(int argc, char **argv) case 'r': if (!getSizeTArg(optarg, &g_logRotateSizeKBytes, 1)) { - logcat_panic(true, "Invalid parameter %s to -r\n", optarg); + logcat_panic(HELP_TRUE, + "Invalid parameter \"%s\" to -r\n", optarg); } break; case 'n': if (!getSizeTArg(optarg, &g_maxRotatedLogs, 1)) { - logcat_panic(true, "Invalid parameter %s to -n\n", optarg); + logcat_panic(HELP_TRUE, + "Invalid parameter \"%s\" to -n\n", optarg); } break; case 'v': - err = setLogFormat (optarg); + if (!strcmp(optarg, "help") || !strcmp(optarg, "--help")) { + show_format_help(); + exit(0); + } + err = setLogFormat(optarg); if (err < 0) { - logcat_panic(true, "Invalid parameter %s to -v\n", optarg); + logcat_panic(HELP_FORMAT, + "Invalid parameter \"%s\" to -v\n", optarg); } hasSetLogFormat |= err; break; @@ -932,17 +989,20 @@ int main(int argc, char **argv) break; case ':': - logcat_panic(true, "Option -%c needs an argument\n", optopt); + logcat_panic(HELP_TRUE, + "Option -%c needs an argument\n", optopt); break; default: - logcat_panic(true, "Unrecognized Option %c\n", optopt); + logcat_panic(HELP_TRUE, + "Unrecognized Option %c\n", optopt); break; } } if (g_maxCount && got_t) { - logcat_panic(true, "Cannot use -m (--max-count) and -t together\n"); + logcat_panic(HELP_TRUE, + "Cannot use -m (--max-count) and -t together\n"); } if (g_printItAnyways && (!g_regex || !g_maxCount)) { // One day it would be nice if --print -v color and --regex @@ -968,12 +1028,12 @@ int main(int argc, char **argv) } if (g_logRotateSizeKBytes != 0 && g_outputFileName == NULL) { - logcat_panic(true, "-r requires -f as well\n"); + logcat_panic(HELP_TRUE, "-r requires -f as well\n"); } if (setId != NULL) { if (g_outputFileName == NULL) { - logcat_panic(true, "--id='%s' requires -f as well\n", setId); + logcat_panic(HELP_TRUE, "--id='%s' requires -f as well\n", setId); } std::string file_name = android::base::StringPrintf("%s.id", g_outputFileName); @@ -1003,7 +1063,8 @@ int main(int argc, char **argv) if (forceFilters) { err = android_log_addFilterString(g_logformat, forceFilters); if (err < 0) { - logcat_panic(false, "Invalid filter expression in logcat args\n"); + logcat_panic(HELP_FALSE, + "Invalid filter expression in logcat args\n"); } } else if (argc == optind) { // Add from environment variable @@ -1013,7 +1074,7 @@ int main(int argc, char **argv) err = android_log_addFilterString(g_logformat, env_tags_orig); if (err < 0) { - logcat_panic(true, + logcat_panic(HELP_TRUE, "Invalid filter expression in ANDROID_LOG_TAGS\n"); } } @@ -1023,7 +1084,8 @@ int main(int argc, char **argv) err = android_log_addFilterString(g_logformat, argv[i]); if (err < 0) { - logcat_panic(true, "Invalid filter expression '%s'\n", argv[i]); + logcat_panic(HELP_TRUE, + "Invalid filter expression '%s'\n", argv[i]); } } } @@ -1109,17 +1171,20 @@ int main(int argc, char **argv) } // report any errors in the above loop and exit if (openDeviceFail) { - logcat_panic(false, "Unable to open log device '%s'\n", openDeviceFail); + logcat_panic(HELP_FALSE, + "Unable to open log device '%s'\n", openDeviceFail); } if (clearFail) { - logcat_panic(false, "failed to clear the '%s' log\n", clearFail); + logcat_panic(HELP_FALSE, + "failed to clear the '%s' log\n", clearFail); } if (setSizeFail) { - logcat_panic(false, "failed to set the '%s' log size\n", setSizeFail); + logcat_panic(HELP_FALSE, + "failed to set the '%s' log size\n", setSizeFail); } if (getSizeFail) { - logcat_panic(false, "failed to get the readable '%s' log size", - getSizeFail); + logcat_panic(HELP_FALSE, + "failed to get the readable '%s' log size", getSizeFail); } if (setPruneList) { @@ -1130,11 +1195,11 @@ int main(int argc, char **argv) if (asprintf(&buf, "%-*s", (int)(bLen - 1), setPruneList) > 0) { buf[len] = '\0'; if (android_logger_set_prune_list(logger_list, buf, bLen)) { - logcat_panic(false, "failed to set the prune list"); + logcat_panic(HELP_FALSE, "failed to set the prune list"); } free(buf); } else { - logcat_panic(false, "failed to set the prune list (alloc)"); + logcat_panic(HELP_FALSE, "failed to set the prune list (alloc)"); } } @@ -1165,7 +1230,7 @@ int main(int argc, char **argv) } if (!buf) { - logcat_panic(false, "failed to read data"); + logcat_panic(HELP_FALSE, "failed to read data"); } // remove trailing FF @@ -1217,7 +1282,7 @@ int main(int argc, char **argv) int ret = android_logger_list_read(logger_list, &log_msg); if (ret == 0) { - logcat_panic(false, "read: unexpected EOF!\n"); + logcat_panic(HELP_FALSE, "read: unexpected EOF!\n"); } if (ret < 0) { @@ -1226,12 +1291,12 @@ int main(int argc, char **argv) } if (ret == -EIO) { - logcat_panic(false, "read: unexpected EOF!\n"); + logcat_panic(HELP_FALSE, "read: unexpected EOF!\n"); } if (ret == -EINVAL) { - logcat_panic(false, "read: unexpected length.\n"); + logcat_panic(HELP_FALSE, "read: unexpected length.\n"); } - logcat_panic(false, "logcat read failure"); + logcat_panic(HELP_FALSE, "logcat read failure"); } for (d = devices; d; d = d->next) { diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index bc0ea525c..18067dc16 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -25,6 +25,7 @@ #include #include +#include #include #include @@ -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")); + } + } + +}