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

Commit 030b4d1b authored by Mark Salyzyn's avatar Mark Salyzyn Committed by Gerrit Code Review
Browse files

Merge changes I596b8706,I262c0377,Iaf2bee97 

* changes:
  liblog: allow event tags to include some punctuations
  liblog: logprint supports number of seconds time event field
  logcat: test: standardize rest() to let logs land when injecting
parents 42d524f7 01bdb04b

liblog/event.logtags

+1 −0
Original line number Diff line number Diff line
@@ -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.

liblog/event_tag_map.cpp

+31 −22
Original line number Diff line number Diff line
@@ -229,9 +229,16 @@ int EventTagMap::find(MapString&& tag) const { 
  return it->second;

}



// The position after the end of a valid section of the tag string,

// caller makes sure delimited appropriately.

static const char* endOfTag(const char* cp) {

  while (*cp && (isalnum(*cp) || strchr("_.-@,", *cp))) ++cp;

  return cp;

}



// Scan one tag line.

//

// "*pData" should be pointing to the first digit in the tag number.  On

// "pData" should be pointing to the first digit in the tag number.  On

// successful return, it will be pointing to the last character in the

// tag line (i.e. the character before the start of the next line).

//
@@ -241,10 +248,11 @@ int EventTagMap::find(MapString&& tag) const { 
// data and it will outlive the call.

//

// Returns 0 on success, nonzero on failure.

static int scanTagLine(EventTagMap* map, char** pData, int lineNum) {

  char* cp;

  unsigned long val = strtoul(*pData, &cp, 10);

  if (cp == *pData) {

static int scanTagLine(EventTagMap* map, const char*& pData, int lineNum) {

  char* ep;

  unsigned long val = strtoul(pData, &ep, 10);

  const char* cp = ep;

  if (cp == pData) {

    if (lineNum) {

      fprintf(stderr, OUT_TAG ": malformed tag number on line %d\n", lineNum);

    }
@@ -273,14 +281,13 @@ static int scanTagLine(EventTagMap* map, char** pData, int lineNum) { 
  }



  const char* tag = cp;

  // Determine whether "c" is a valid tag char.

  while (isalnum(*++cp) || (*cp == '_')) {

  }

  cp = endOfTag(cp);

  size_t tagLen = cp - tag;



  if (!isspace(*cp)) {

    if (lineNum) {

      fprintf(stderr, OUT_TAG ": invalid tag chars on line %d\n", lineNum);

      fprintf(stderr, OUT_TAG ": invalid tag char %c on line %d\n", *cp,

              lineNum);

    }

    errno = EINVAL;

    return -1;
@@ -311,9 +318,9 @@ static int scanTagLine(EventTagMap* map, char** pData, int lineNum) { 


  while (*cp != '\n') ++cp;

#ifdef DEBUG

  fprintf(stderr, "%d: %p: %.*s\n", lineNum, tag, (int)(cp - *pData), *pData);

  fprintf(stderr, "%d: %p: %.*s\n", lineNum, tag, (int)(cp - pData), pData);

#endif

  *pData = cp;

  pData = cp;



  if (lineNum) {

    if (map->emplaceUnique(tagIndex,
@@ -341,9 +348,9 @@ static const char* eventTagFiles[NUM_MAPS] = { 


// Parse the tags out of the file.

static int parseMapLines(EventTagMap* map, size_t which) {

  char* cp = static_cast<char*>(map->mapAddr[which]);

  const char* cp = static_cast<char*>(map->mapAddr[which]);

  size_t len = map->mapLen[which];

  char* endp = cp + len;

  const char* endp = cp + len;



  // insist on EOL at EOF; simplifies parsing and null-termination

  if (!len || (*(endp - 1) != '\n')) {
@@ -370,7 +377,7 @@ static int parseMapLines(EventTagMap* map, size_t which) { 
        lineStart = false;

      } else if (isdigit(*cp)) {

        // looks like a tag; scan it out

        if (scanTagLine(map, &cp, lineNum) != 0) {

        if (scanTagLine(map, cp, lineNum) != 0) {

          if (!which || (errno != EMLINK)) {

            return -1;

          }
@@ -495,14 +502,13 @@ static const TagFmt* __getEventTag(EventTagMap* map, unsigned int tag) { 
  int ret = asprintf(&buf, command_template, tag);

  if (ret > 0) {

    // Add some buffer margin for an estimate of the full return content.

    char* cp;

    size_t size =

        ret - strlen(command_template) +

        strlen("65535\n4294967295\t?\t\t\t?\t# uid=32767\n\n\f?success?");

    if (size > (size_t)ret) {

      cp = static_cast<char*>(realloc(buf, size));

      if (cp) {

        buf = cp;

      char* np = static_cast<char*>(realloc(buf, size));

      if (np) {

        buf = np;

      } else {

        size = ret;

      }
@@ -512,10 +518,12 @@ static const TagFmt* __getEventTag(EventTagMap* map, unsigned int tag) { 
    // Ask event log tag service for an existing entry

    if (__send_log_msg(buf, size) >= 0) {

      buf[size - 1] = '\0';

      unsigned long val = strtoul(buf, &cp, 10);        // return size

      char* ep;

      unsigned long val = strtoul(buf, &ep, 10);  // return size

      const char* cp = ep;

      if ((buf != cp) && (val > 0) && (*cp == '\n')) {  // truncation OK

        ++cp;

        if (!scanTagLine(map, &cp, 0)) {

        if (!scanTagLine(map, cp, 0)) {

          free(buf);

          return map->find(tag);

        }
@@ -573,8 +581,9 @@ LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, 
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;

  }

liblog/logprint.c

+41 −2
Original line number Diff line number Diff line
@@ -326,6 +326,7 @@ android_log_formatFromString(const char* formatString) { 
  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 @@ enum objectType { 
  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 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, 
  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 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, 
   * 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 @@ static int android_log_printBinaryEvent(const unsigned char** pEventData, 
            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"); */

logcat/event.logtags

+1 −0
Original line number Diff line number Diff line
@@ -30,6 +30,7 @@ 
# 4: Number of allocations

# 5: Id

# 6: Percent

# s: Number of seconds (monotonic time)

# Default value for data of type int/long is 2 (bytes).

#

# TODO: generate ".java" and ".h" files with integer constants from this file.

logcat/tests/logcat_test.cpp

+90 −24
Original line number Diff line number Diff line
@@ -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 @@ TEST(logcat, buckets) { 
#undef LOG_TAG

#define LOG_TAG "inject"

    RLOGE(logcat_executable ".buckets");

    sleep(1);

    rest();



    ASSERT_TRUE(NULL !=

                (fp = logcat_popen(
@@ -1412,7 +1424,7 @@ TEST(logcat, regex) { 
    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 @@ TEST(logcat, maxcount) { 
    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, ...) 


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 @@ static bool End_to_End(const char* tag, const char* fmt, ...) { 
        // 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 @@ TEST(logcat, descriptive) { 
        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 @@ TEST(logcat, descriptive) { 
        {

            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 @@ TEST(logcat, descriptive) { 
        {

            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 @@ TEST(logcat, descriptive) { 
        {

            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 @@ TEST(logcat, descriptive) { 
        {

            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 @@ TEST(logcat, descriptive) { 
        {

            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 @@ TEST(logcat, descriptive) { 
    {

        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) {