Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 4fd0507b authored by Mark Salyzyn's avatar Mark Salyzyn
Browse files

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
parent 530711b3

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"));

        }

    }



}