一次bookkeeper inode泄露问题的排查经历

已知的未知

某日笔者在漫游巡检负责的bookkeeper服务时发现bookie进程hold了一个已删除文件的文件描述符，如下，笔者当时不知道这个文件干嘛的，哪个组件创建和打开的，这属于已知的未知，因此需要一探究竟 首先这种情况在linux上虽然在文件目录上看不到这个文件，但是其inode还在，还是可以找回这个文件的，例如用下面这个命令转存pid 28335，fd编号276的文件

cat /proc/28335/fd/276 > /tmp/copy

文件不大4096，直接看一下文件内容，也没啥价值不知道做什么的

然后笔者又去翻看了一下bookkeeper代码，并没有发现相关写该文件的代码。同时又检查了其它环境的服务，发现都存在这种情况，通过heapdump分析也找不到fd编号276的记录

select * from java.io.FileDescriptor fd where fd.fd = 276

同时搜其它文件是可以搜到的

另外笔者又去找别人check了一下其它环境是否存在这种情况，答复是没有；不过既然这个问题在我这里是必现就好查，因此单独起了一个测试环境上strace，果然重现了

strace -ff -o /tmp/strace.out /opt/java/bin/java balabala

# lsof -Pn -p `jps | awk '$2 == "Main" {print $1}'` | grep deleted
java    21419 root  352u      REG              202,2       4096    524642 /tmp/ffirkKtRJ (deleted)
# grep /tmp/ffirkKtRJ strace.out.*
strace.out.21696:open("/tmp/ffirkKtRJ", O_RDWR|O_CREAT|O_EXCL, 0600) = 352
strace.out.21696:unlink("/tmp/ffirkKtRJ")                = 0

现在知道具体操作该文件的线程id了，可见是先open然后unlink都是在这个线程21696操作的，看一下这个线程是什么

top -b -Hp `jps | awk '$2 == "Main" {print $1}'` | grep 21696
21696 root      20   0 8315728 245388  22076 S  0.0  1.5   0:00.24 BookieJournal-3
21696 root      20   0 8315728 245388  22076 S  0.0  1.5   0:00.24 BookieJournal-3
^C

然后用async-profiler (opens new window)去profile unlink这个syscall，这个问题如果能拿到stacktrace，基本也就有眉目了

/opt/java/bin/java -agentpath:/path/to/async-profiler-2.8-linux-x64/build/libasyncProfiler.so=start,event=unlink,threads balabala

果然，unlink是从org.apache.bookkeeper.util.NativeIO中发起的，细看一下代码发现引入了net.java.dev.jna:jna这个包，这个包里面包含了一些JNI的代码，checkout指定的版本，在这里:

原来是bookie中NativeIO这个类用到了jna (opens new window)这个组件，jna这个组件又引用了libffi (opens new window) 至此到这里也就算是揭开了上面的已知的未知

笔者当时不知道这个文件干嘛的，哪个组件创建和打开的

总结

1. 为什么这个问题在笔者这里必现，但是找别人check其它环境没有类似的情况？ 因为这里别人的环境是较新的版本，已经把jna组件拿掉了，详情可见: https://github.com/apache/bookkeeper/pull/3824
2. 这个问题查下来是无用但是有趣，减少了一个已知的未知风险
3. 这里要感谢一下bookkeeper社区的Chen Hang (opens new window)，帮忙check以及提供思路