Android logd日志原理_android bugreport的日志跟logd不一致

1. 概述

  无论是Android系统开发，还是应用开发，都离不开log，Androd上层采用logcat输出log。因此我们这次基于Android源码9.0，解读logd的日志记录过程。

代码路径：

frameworks/base/core/java/android/util/
    - Log.java
    - Slog.java
    - EventLog.java

frameworks/base/core/jni/android_util_Log.cpp

/system/core/logcat/logcat.cpp
/system/core/liblog/logger_write.c
/system/core/liblog/uio.c
/system/core/liblog/properties.c

/system/core/logd/
    - main.cpp
    - LogBuffer.cpp
    - LogStatistics.cpp
/system/core/libsysutils/src/SocketListener.cpp
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

logcat命令说明

可通过adb命令直接输出指定的log：

logcat -b events // 输出指定buffer的log
logcat -s "ActivityManager"
logcat -L //上次重启时的log
logcat -f [filename] //将log保存到指定文件
logcat -g //缓冲区大小
logcat -S  //统计log信息
1
2
3
4
5
6

-b 默认是指-b main -b system -b crash，当然一可以指定其他参数，或者直接指定all。

2. log函数使用

2.1 Java层

默认定义了5个Buffer缓冲区，如下：

log级别：

2.2 Kernel层

Linux Kernel最常使用的是printk，用法如下：

//第一个参数是级别， 第二个是具体log内容
printk(KERN_INFO x);
1
2

日志级别的定义位于kernel/include/linux/printk.h文件，如下：

日志输出到文件/proc/kmsg，可通过cat /proc/kmsg来获取内核log信息。

cat /proc/sys/kernel/printk

3. 原理分析

3.1 Log.i

[-> android/util/Log.java]

首先我们重点看下android.util.Log类：
Log类定义较简单，无父类，final修饰，不可继承。构造函数是private，不可实例化。

public static int i(String tag, String msg) {
    // [见小节3.2]
    return println_native(LOG_ID_MAIN, INFO, tag, msg);
}
1
2
3
4

Log.java中的方法都是输出到main buffer, 其中println_native是Native方法， 通过JNI调用如下方法。

3.2 println_native

[-> android_util_Log.cpp]
传入的三个参数分别是：LOG_ID_MAIN（类型），INFO（级别），tag（标签），msg（日志信息），实现如下：

/*
 * In class android.util.Log:
 *  public static native int println_native(int buffer, int priority, String tag, String msg)
 */
static jint android_util_Log_println_native(JNIEnv* env, jobject clazz,
        jint bufID, jint priority, jstring tagObj, jstring msgObj)
{
    const char* tag = NULL;
    const char* msg = NULL;

    ...

	//获取log标签和内容
    if (tagObj != NULL)
        tag = env->GetStringUTFChars(tagObj, NULL);
    msg = env->GetStringUTFChars(msgObj, NULL);

	// [见小节3.3]
    int res = __android_log_buf_write(bufID, (android_LogPriority)priority, tag, msg);

    if (tag != NULL)
        env->ReleaseStringUTFChars(tagObj, tag);
    env->ReleaseStringUTFChars(msgObj, msg);

    return res;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

3.3 __android_log_buf_write

[-> logger_write.c]

注意：第一次真正执行的方法是：__write_to_log_init，初始化后write_to_log的的方法实现变为：__write_to_log_daemon。详细参见__write_to_log_init的方法实现

LIBLOG_ABI_PUBLIC int __android_log_buf_write(int bufID, int prio,
                                              const char* tag, const char* msg) {
  struct iovec vec[3];
  char tmp_tag[32];

  if (!tag) tag = "";

  /* XXX: This needs to go! */
  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;
        //满足以上条件的tag，则默认输出到radio缓冲区，并修改相应的tags
        snprintf(tmp_tag, sizeof(tmp_tag), "use-Rlog/RLOG-%s", tag);
        tag = tmp_tag;
      /* FALLTHRU */
      default:
        break;
    }
  }

#if __BIONIC__
  if (prio == ANDROID_LOG_FATAL) {
    android_set_abort_message(msg);
  }
#endif

  vec[0].iov_base = (unsigned char*)&prio;
  vec[0].iov_len = 1;
  vec[1].iov_base = (void*)tag;
  vec[1].iov_len = strlen(tag) + 1;
  vec[2].iov_base = (void*)msg;
  vec[2].iov_len = strlen(msg) + 1;
  
  // [见小节3.4]
  return write_to_log(bufID, vec, 3);
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67

• 对于满足特殊条件的tag，则会输出到LOG_ID_RADIO缓冲区；
• vec数组依次记录着log的级别，tag, msg.

其中write_to_log函数指针指向__write_to_log_init

static int (*write_to_log)(log_id_t, struct iovec* vec,
                           size_t nr) = __write_to_log_init;
1
2

3.4 write_to_log

[-> logger_write.c]

static int __write_to_log_init(log_id_t log_id, struct iovec* vec, size_t nr) {
  int ret, save_errno = errno;

  __android_log_lock();// 加锁

  if (write_to_log == __write_to_log_init) {
    ret = __write_to_log_initialize();//执行log初始化
    if (ret < 0) {
      __android_log_unlock();
      if (!list_empty(&__android_log_persist_write)) {
        __write_to_log_daemon(log_id, vec, nr);//【见小节3.5】
      }
      errno = save_errno;
      return ret;
    }

    write_to_log = __write_to_log_daemon;
  }

  __android_log_unlock();// 去锁

  ret = write_to_log(log_id, vec, nr);
  errno = save_errno;
  return ret;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

首先会执行初始化方法__write_to_log_initialize，作用是：为集合__android_log_transport_write设置各类writer，例如logdLoggerWrite，pmsgLoggerWrite等，然后依次调用writer的open方法，例如logdLoggerWrite#logdOpen方法，如果打开失败，则关闭。

logdLoggerWrite#logdOpen方法，代码位置：system/core/liblog/logd_writer.c，其实现是：

/* log_init_lock assumed */
static int logdOpen() {
    // ...
    int sock = TEMP_FAILURE_RETRY(
        socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));   // 注意：SOCK_DGRAM代表着UDP通信，SOCK_NONBLOCK非阻塞式（效率高）
    // ...
    strcpy(un.sun_path, "/dev/socket/logdw");
 
    if (TEMP_FAILURE_RETRY(connect(sock, (struct sockaddr*)&un,
                                     sizeof(struct sockaddr_un))) < 0) {
    // ...
}
1
2
3
4
5
6
7
8
9
10
11
12

接下来进入真正写log的方法.

3.5 __write_to_log_daemon

static int __write_to_log_daemon(log_id_t log_id, struct iovec* vec, size_t nr) {
    struct android_log_transport_write* node;
    int ret, save_errno;
    struct timespec ts;
    size_t len, i;
    // ...
    clock_gettime(android_log_clockid(), &ts);         // 获得日志时间戳
   
    if (log_id == LOG_ID_SECURITY) {
         // ...
    } else if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) {
         // ...
    } else {
        /* Validate the incoming tag, tag content can not split across iovec */
        char prio = ANDROID_LOG_VERBOSE;
        const char* tag = vec[0].iov_base;
 
        // ...
        // 变量prio存储vec[0].iov_base，例如2（VERBOSE），tag存储vec[1].iov_base
 
       if (!__android_log_is_loggable_len(prio, tag, len - 1, ANDROID_LOG_VERBOSE)) {     //如果当前打印的log级别低于系统设置的级别，会直接返回，不会打印。默认是：ANDROID_LOG_VERBOSE（2），系统设置的级别来自于属性：persist.log.tag 或 log.tag
             errno = save_errno;
             return -EPERM;
        }
   }
 
   //....
   // 以下是核心方法实现
   write_transport_for_each(node, &__android_log_transport_write) {
       if (node->logMask & i) {
           ssize_t retval;
           retval = (*node->write)(log_id, &ts, vec, nr);
           if (ret >= 0) {
               ret = retval;
           }
       }
    }
 
    write_transport_for_each(node, &__android_log_persist_write) {
        if (node->logMask & i) {
            (void)(*node->write)(log_id, &ts, vec, nr);
        }
    }
 
    errno = save_errno;
    return ret;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47

  在上面会看到将循环调用所有writer的write方法来传输日志，举个例子logdLoggerWrite的write方法（之前已调用其logdOpen方法：建立Socket连接，path：/dev/socket/logdw）：

static int logdWrite(log_id_t logId, struct timespec* ts, struct iovec* vec,
                     size_t nr) {
 
 
    // ...
    /*
     * The write below could be lost, but will never block.
     *
     * ENOTCONN occurs if logd has died.
     * ENOENT occurs if logd is not running and socket is missing.
     * ECONNREFUSED occurs if we can not reconnect to logd.
     * EAGAIN occurs if logd is overloaded.
     */
    if (sock < 0) {
        ret = sock;
    } else {
        ret = TEMP_FAILURE_RETRY(writev(sock, newVec, i));    // 通过socket写数据
        if (ret < 0) {
            ret = -errno;
        }
   }
   // ...
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

3.6 小节

  一句话总结就是Log.i()最终是通过调用write()向logd守护进程的socket(“/dev/socket/logdw”)端写入需要打印的日志信息。 接下来再来看logd的工作过程。

4. logd守护进程

  下一步是Logd的逻辑分析，即接收到socket通信传输后的数据，该如何处理：
logd是由init进程所启动的守护进程，启动代码参考：system/core/rootdir/init.rc。Logd进程启动时创建3个Socket通道，用于进程间通信，代码实现：system/core/logd/logd.rc，如下：

service logd /system/bin/logd
    socket logd stream 0666 logd logd
    socket logdr seqpacket 0666 logd logd
    socket logdw dgram+passcred 0222 logd logd
    file /proc/kmsg r
    file /dev/kmsg w
    user logd
    group logd system package_info readproc
    writepid /dev/cpuset/system-background/tasks
//...
1
2
3
4
5
6
7
8
9
10

我们可以通过ss -pl查看socket连接：

4.1 main()

[-> /system/core/logd/main.cpp]

  进程启动后，入口方法：system/core/logd/main.cpp，其中入口的main方法实现不复杂，主要创建LogBuffer，然后启动5个listener，一般重要的是前三个：LogReader，LogListener，CommandListener，全部继承于SocketListener（system/core/libsysutils），另外还有2个listener：LogAudit（监听NETLINK_AUDIT，与selinux有关），LogKlog，这里不做深究。

int main(int argc, char* argv[]) {
    // ...
     
    // LogBuffer，作用：存储所有的日志信息
    logBuf = new LogBuffer(times);
     
    // LogReader监听Socket（/dev/socket/logdr），作用：当客户端连接logd后，LogReader将LogBuffer中的日志写给客户端。线程名：logd.reader，通过prctl(PR_SET_NAME, "logd.reader");设定
    LogReader* reader = new LogReader(logBuf);
    if (reader->startListener()) {
        exit(1);
    }
 
    // LogListener监听Socket（/dev/socket/logdw），作用：接收传来的日志信息，写入LogBuffer；同时LogReader将新的日志传给已连接的客户端。线程名：logd.writer
    LogListener* swl = new LogListener(logBuf, reader);
    if (swl->startListener(600)) {
        exit(1);
    }
 
    //CommandListener监听Socket（/dev/socket/logd），作用：接收发来的命令。线程名：logd.control
    CommandListener* cl = new CommandListener(logBuf, reader, swl);
    if (cl->startListener()) {
        exit(1);
    }
    // ...
    exit(0);
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

该方法功能:

1. LogReader: 监听/dev/socket/logdr, 当client连接上则将buffer信息写入client. 所对应线程名”logd.reader”
2. LogListener: 监听/dev/socket/logdw, 新日志添加到LogBuffer, 并且LogReader发送更新给已连接的client. 所对应线程名”logd.writer”
3. CommandListener: 监听/dev/socket/logd, 处理logd管理命令. 所对应线程名”logd.control”
4. LogAudit: 所对应线程名”logd.auditd”
5. LogKlog: 所对应线程名”logd.klogd”
6. 入口reinit_thread_start: 所对应线程名”logd.daemon”

  另外，ANDROID_SOCKET_NAMESPACE_RESERVED代表位于/dev/socket名字空间。 通过adb命令，可以看到logd进程有几个子线程。

  接下来，继续回到前面log输出过程，接下来进入logd的LogListener处理过程，如下

4.2 LogListener.cpp

  首先看LogListener，当有对端进程通过Socket传递过来数据后，onDataAvailable方法被调用，其中主要是解析数据、调用LogBuffer->log方法存储日志信息，调用LogReader→notifyNewLog方法通知有新的日志信息，以便发送给其客户端。如下：

bool LogListener::onDataAvailable(SocketClient* cli) {
    // ...
    // 1. 调用LogBuffer->log方法存储日志信息
    int res = logbuf->log(
            logId, header->realtime, cred->uid, cred->pid, header->tid, msg,
            ((size_t)n <= USHRT_MAX) ? (unsigned short)n : USHRT_MAX);
 
    // 2. 调用LogReader→notifyNewLog方法通知有新的日志信息，以便发送给其客户端
    if (res > 0 && reader != nullptr) {
        reader->notifyNewLog(static_cast<log_mask_t>(1 << logId));
    }
    // ...
}
1
2
3
4
5
6
7
8
9
10
11
12
13

4.3 LogBuffer.cpp

  继续看LogBuffer的log方法，代码位置：system/core/logd/LogBuffer.cpp

int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
                   pid_t tid, const char* msg, unsigned short len) {
    // ...
    // 低于当前设定的日志优先级，返回
    if (!__android_log_is_loggable_len(prio, tag, tag_len,
                                       ANDROID_LOG_VERBOSE)) {
        // Log traffic received to total
        wrlock();
        stats.addTotal(elem);
        unlock();
        delete elem;
        return -EACCES;
    }
 
    // 调用重载的log方法
    log(elem);
    unlock();
 
    return len;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

  继续看log方法，主要作用是通过比对新进日志信息的时间，将其插入到正确的存储位置。所有日志存储在mLogElements变量中，其类型是：typedef std::list<LogBufferElement*>

void LogBuffer::log(LogBufferElement* elem) {
      // 插入正确位置，逻辑相对复杂，摘取其中关键一段
      do {
            last = it;
            if (__predict_false(it == mLogElements.begin())) {
                  break;
            }
            --it;
      } while (((*it)->getRealTime() > elem->getRealTime()) && (!end_set || (end <= (*it)->getRealTime())));
            mLogElements.insert(last, elem);
      }
 
     // ...
     stats.add(elem);           // 初步看做一些统计工作，例如通过数组，统计不同类型日志的打印次数，不同类型日志的字符串总长度等，并且将日志信息以uid, pid, tid, tag等为单位，保存elem信息至不同的hashtable中
     maybePrune(elem->getLogId());
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

  其中maybePrune方法的作用很重要，当不同类型的log日志size超过最大限制时，会触发对已保存日志信息的裁剪，一次裁剪量约为10%：

void LogBuffer::maybePrune(log_id_t id) {
    size_t sizes = stats.sizes(id);                                         // 来自LogStatistics->mSizes[id]变量的值，统计不同日志类型的当前日志长度（msg）
    unsigned long maxSize = log_buffer_size(id);            // 取不同日志类型的日志长度最大值
    if (sizes > maxSize) {
        size_t sizeOver = sizes - ((maxSize * 9) / 10);
        size_t elements = stats.realElements(id);
        size_t minElements = elements / 100;
        if (minElements < minPrune) {                               // minPrune值是4
            minElements = minPrune;                                 // minElements默认是全部日志元素数的百分之一，最小值是4
        }
        unsigned long pruneRows = elements * sizeOver / sizes;  // 需要裁剪的元素个数，最小值是4个，最大值是256个，正常是总元素的比例：1 - （maxSize/sizes）* 0.9 = 约等于10%
        if (pruneRows < minElements) {
            pruneRows = minElements;
        }
        if (pruneRows > maxPrune) {                               // maxPrune值是256
            pruneRows = maxPrune;
        }
        prune(id, pruneRows);                                           // 如果日志存储已越界，则最终走到prune裁剪函数中处理，pruneRows是需要裁剪的元素个数
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

重要备注：不同日志类型的日志长度最大值，由上到下取值顺序：
persist.logd.size.* // 例如：persist.logd.size.main、persist.logd.size.radio、persist.logd.size.events、persist.logd.size.system、persist.logd.size.crash、persist.logd.size.stats、persist.logd.size.security、persist.logd.size.kernel
ro.logd.size.* // 例如：ro.logd.size.main、ro.logd.size.radio、ro.logd.size.events、ro.logd.size.system、ro.logd.size.crash、ro.logd.size.stats、ro.logd.size.security、ro.logd.size.kernel
persist.logd.size // 设置APP：开发者选项-日志记录器缓冲区大小，默认256K
ro.logd.size
LOG_BUFFER_MIN_SIZE // 64K，条件是如果ro.config.low_ram是true，表示低内存手机
LOG_BUFFER_SIZE // 256K

另外可以用adb logcat -g命令查看缓冲区大小
具体执行的prune裁剪方法这里没有深究，感兴趣的同学可以看下system/core/logd/LogBuffer.cpp#prune方法，大致思路是：

1. 支持黑/白名单（详见LogWhiteBlackList.cpp，uid + pid。注意：adb logcat -P可设置），白名单中不裁剪
2. 优先裁剪黑名单、打印日志最多的uid，system uid中打印日志最多的pid

至此一次完整的：APP调用Log.v方法打印VERBOSE日志，调用执行过程完毕！