从一次日志丢失所想到的

最近我在编写一个 Android 上的驱动程序,这个驱动程序的某些部分用到了 Unix domain socket,守护进程和客户端进程使用 C/S 模式进行通信。在调试程序的时候发现一个非常奇怪的问题:如果客户端开启若干个线程连上 socket,send/recv 若干消息之后立即退出进程,从日志上看,server 端有 10% 左右的概率无法正常回收资源。

一开始我以为是我自己程序写的有问题,毕竟这个驱动是使用纯 C 语言实现的,并且用到了 epoll 的 ET 模式,这种非阻塞的编程模型的确有许多微妙的地方,一不小心就容易出错。我排查了很久都没有发现问题所在,更有趣的是,虽然看起来我的程序无法回收资源,但是在压力测试下他也能正常工作,完全没有资源泄漏的迹象;实在没办法,我就祭出了大杀器 strace。不看不知道,一看就好笑:strace 显示,我的程序逻辑是正常的,它正确地调用了相关的资源释放函数!但是,logcat 中没有相关的日志,在客户端退出之后 server 端的日志就戛然而止了。看起来,好像不是我程序的问题,而是系统的 logcat 丢失了日志?

出于好奇,我就去简单看了下 Android 上 logcat 的实现。原来,logcat 也用了 C/S 模式,有个 logd 的守护进程工作在 server 端,各个进程通过 Log.d 等方法输出日志的时候,实际上也是通过一个 socket 以异步的方式传递给了 logd,logd 再把日志输出到 logcat。当我看到客户端连接 logd 的代码的时候,就立马明白了。。我们看代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
int LogListener::GetLogSocket() {
static const char socketName[] = "logdw";
int sock = android_get_control_socket(socketName);

if (sock < 0) { // logd started up in init.sh
sock = socket_local_server(
socketName, ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_DGRAM);

int on = 1;
if (setsockopt(sock, SOL_SOCKET, SO_PASSCRED, &on, sizeof(on))) {
return -1;
}
}
return sock;
}

以上代码摘自 AOSP master 分支

原来我们的 logcat 的 socket 使用的是 UDP !

UDP 是User Datagram Protocol的简称, 中文名是用户数据报协议,是OSI(Open System Interconnection,开放式系统互联) 参考模型中一种无连接的传输层协议,提供面向事务的简单不可靠信息传送服务,IETF RFC 768 [1] 是UDP的正式规范。UDP在IP报文的协议号是17。(摘自百度百科)

与 TCP 不同,UDP 是不保证可靠传输的。我的程序用的 TCP,因此在 send/recv 完数据之后即使进程退出,内核也会保证数据能正确地发送到对端(在对端正常的情况下);而 logcat 使用的 UDP,一旦进程退出,数据包是有可能无法送达 logd 的。顺便一提,除了这种丢日志的情形之外,还有一种更常见的情况,就是 logcat 觉得你的日志太频繁把你阉割了,这种情况下我们会在日志中看到 “chatty” 等字样,只需要设置 logcat 的相关属性就可以解决了。

这不禁让我想起好几年前我在知乎上回答的一个问题: JAVA中:String的equals方法会不会因为恶劣的环境(海啸地震、外星人入侵等)导致运行出错?

还有,我之前在写太极的时候,发现有个 App 无论如何也注入不进去;后来发现是因为这个 App 把应用的日志全部重定向到了 /dev/null,使得我们无法看到任何日志,然后误以为是程序逻辑没有执行。

实际上,除了代码之外,我们经常会遇到类似的问题。归根结底,就是我们眼睛看到的东西看起来跟“事实”不一致。很多时候,我们会无意识地相信眼睛看到的,毕竟,「眼见为实」嘛!不过,如果“亲眼所见” 最终得出荒谬结论的时候,一定要想想是不是“看到的”有问题。

真实世界中没有鬼,如果有,也只能代表眼睛看到了鬼。