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

# 已知的未知

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

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

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

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

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

image.png

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

另外笔者又去找别人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

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

原来是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以及提供思路