背景

为了确保软件能够使用正确的文件进行工作，开发团队在软件中实现了一个文件校验功能。其处理流程如下图所示。

graph TD
Java程序 --校验扫描结果--> 数据库
Java程序 --执行--> Bash脚本
Bash脚本 --输出扫描结果--> Java程序
Bash脚本 --SSH--> 服务器1
Bash脚本 --SSH--> 服务器2
Bash脚本 --SSH--> ......
Bash脚本 --SSH--> 服务器N

现象

有时候，在校验文件的过程中，Java程序会输出形如xxx.sh line yy: write error: Resource temporarily unavailable的错误信息。值得注意的是，错误的出现时机没有规律。

事前调查

因为我对write error: Resource temporarily unavailable这个错误不熟悉，所以我想在着手处理这个问题之前先进行一番调查。在Google上搜索了一段时间后，我得到了一条线索：write error: Resource temporarily unavailable与非阻塞（Non-Blocking）的输入模式有关，此模式需要通过设置一个名为O_NONBLOCK的文件状态标志来启用。在非阻塞输入模式下，如果write系统调用由于空间不足等原因无法完成写操作，则会设置EAGAIN错误码，对应的错误信息即为Resource temporarily unavailable。

重现

做好事前准备之后，调试工作正式开始。调试的第一步是重现问题，因为如果问题无法稳定重现，调试工作将难以开展。因为错误是Bash脚本输出的，所以我首先尝试把脚本拎出来执行，观察一下问题会不会重现，结果发现只是直接执行脚本的话，不管是单进程执行还是并发多进程执行都无法重现错误，看来要重现此问题不能只是局限在Bash脚本的范围里，而是要从整体的执行过程入手。为了模拟出Bash脚本生产扫描结果给Java程序消费的情况，我构造了一个如下图所示的场景：创建一个管道文件，在管道一侧并发执行多个脚本，刻意放大输出量，然后在另一侧用cat命令读取管道。当同时运行的脚本进程数达到16个或以上时，问题终于能够稳定重现了。

graph LR
Bash脚本进程1 --写入--> Pipe["管道"]
Bash脚本进程2 --写入--> Pipe
......  --写入--> Pipe
Bash脚本进程N  --写入--> Pipe
Pipe --输出--> cat

初步分析

有了稳定重现问题的方法，接下来的任务就是分析问题的根源。根据目前掌握的信息，我认为Resource temporarily unavailable错误出现的原因有两个，一是Bash进程的stdout被设置了非阻塞模式，二是分配给stdout的缓冲区空间被填满了。确切的说，是这两个因素的共同作用导致了错误的出现。

为了验证这一猜想，我先是浏览了一遍Bash脚本代码（代码的大致结构如下所示），并没有发现任何直接设置O_NONBLOCK的操作。考虑到可能是某些命令间接导致了O_NONBLOCK被设置，我在脚本里加入了一段检测stdout文件状态标志的代码，果然观察到了O_NONBLOCK的出现。然而，当我尝试在出错代码前关闭O_NONBLOCK时，错误依然出现。这让我感到困惑：难道O_NONBLOCK与错误无关？经过多次尝试，我仍然毫无头绪，只好将注意力转向缓冲区方向。

for IP in "${host_ip_list[@]}" # 遍历服务器IP
do
	(
	for item in $(ssh $IP 'scan') # 遍历扫描结果
	do
	    result=$(Process $item) # 处理扫描结果
	    # 在此处加入检测O_NONBLOCK的代码
	    # 在此处加入关闭O_NONBLOCK的代码
	    echo "$result" # 出错的代码行
	done
	) & # 多进程并发扫描服务器
done

为了分析缓冲区相关的问题，我开始阅读Java源代码。经过一番浏览，我发现Java程序是通过Apache Commons Exec库调用Bash脚本的。进一步分析库的源码，我发现该库会分别创建三个线程来处理被执行程序的stdin、stdout和stderr，整个过程如下图所示。于是，我设计了一个简单的验证方案：通过调试工具挂起Apache Commons Exec的stdout处理线程，故意使缓冲区有进无出，从而验证错误是否与缓冲区被占满有关。果不其然，错误出现了。为了进一步对照确认，我在Bash脚本的输出代码块外使用dd程序增加了一层足够大的缓冲区（即 Bash → dd → Java），重新进行试验。这次，错误没有出现。至此，我可以确定缓冲区被占满是导致错误的关键因素之一。

digraph G {
    rankdir=LR
    compound=true

    subgraph cluster_java {
        Java [shape=plaintext]
        Thread1; Thread2; Thread3
    }

    subgraph cluster_bash {
        Bash [shape=plaintext]
        stdin; stdout; stderr
    }

    Java -> Bash [label="执行" ltail="cluster_java" lhead="cluster_bash"]
    Thread1 -> stdin [label="写入数据"]
    Thread2 -> stdout [label="读出数据"]
    Thread3 -> stderr[label="读出数据"]
}

深入挖掘

虽然我已经找到了增加缓冲区大小的解决方案，但是关于O_NONBLOCK的疑团还没有解开。

为了彻底弄清O_NONBLOCK的来源，我使用strace工具追踪了所有与O_NONBLOCK相关的系统调用。在strace的输出中，虽然有许多与O_NONBLOCK相关的记录，但大部分都与Bash脚本的stdout无关。唯一与stdout相关的是ssh子进程的一个fcntl(stdout, F_SETFL, flags|O_NONBLOCK)调用。子进程的fcntl调用是不会影响到父进程的，怀着这样的想法，我忽略了这个线索，却再也找不到其他相关的信息了，调查似乎陷入了死局。

为了找到突破口，我查阅了大量与O_NONBLOCK相关的资料，最终在POSIX Specification里发现：

  1. O_NONBLOCK属于文件描述（file description）的一部分，而每个文件描述符（file descriptor）都会有一个对应的文件描述。
  2. 文件描述符一般由open系统调用创建，而且It shall create an open file description that refers to a file and a file descriptor that refers to that open file description.

沿着这些线索继续调查，我终于找到了突破口，在fork系统调用的文档里，有这么一段话：The child process shall have its own copy of the parent's file descriptors. Each of the child's file descriptors shall refer to the same open file description with the corresponding file descriptor of the parent.原来子进程虽然会拷贝父进程的文件描述符，但是拷贝出来的文件描述符引用的还是父进程原来的文件描述（如下图所示）。O_NONBLOCK的出现就是ssh子进程导致的，是我先入为主地认为子进程修改文件状态标志对父进程没有影响，才走了这么多弯路……现在真相终于大白了。

graph LR
subgraph 父进程
	parent_fd[文件描述符] -- 指向 --> 文件描述
end
subgraph 子进程
	child_fd[文件描述符] -- 指向 --> 文件描述
end
child_fd -- 拷贝 --> parent_fd

总结

这次的调试我花了特别长的时间，其中固然有问题本身较为复杂的原因，但更多地还是因为我犯了错误走了弯路。总的来看，这次调试我犯了下列两个错误：

  1. 没有充分了解错误就开始动手调试。在得知Resource temporarily unavailable与O_NONBLOCK有关时，我就应该先了解清楚O_NONBLOCK的工作原理，而不是急于动手调试。
  2. 先入为主地排除可能的线索。当我过滤掉strace的无关信息后只发现了ssh子进程的fcntl系统调用时，尽管我觉得子进程会影响父进程是不可思议的，但也应该怀疑这就是问题出现的原因，正如福尔摩斯所云：排除所有不可能的，剩下的即使再不可思议，那也是真相。

吃一堑，长一智，希望这次曲折的调试经历能让我意识到在工作中保持开放思维的重要性，争取下次不再吃惯性思维的亏了。

猜您还喜欢