又一个无辜的故障排查

最近团队变动，接手了一堆陌生的应用。磨合期总会各种折腾，忙到昏天黑地，书也没怎么看，荒废啊荒废。

再记一个故障排查。这个写完以后，希望相当长的时间里，不要让我再写这个话题了吧。

1、现象：

一个山寨的数据库同步应用挂了。

2、排查：

2.1、弯路

通过conf/log4j.xml找到“一个”日志文件”（/home/admin/out/logs/automation_sys.log），结果翻了半天，没有看出哪里有问题。

因为是一个分布式应用，部署在3台机器上（3 slave，1 master。s-m之间通过rmi通信）。

所以在master机上看不出来问题，就去看几个slave，结果日志里一样没有什么错误。

2.2、正解

无奈，跑到log文件夹下面grep 出错的时间，很容易就看到了下面的异常（host1是被处理过的机器名）。

[0327 15:53:56 674 ERROR] [main] master.action.DefaultAction - host1 error is java.util.concurrent.ExecutionException: org.springframework.remoting.RemoteConnectFailureException: Cannot connect to remote service [rmi://host1:3099/RmiDispatcherService]; nested exception is java.rmi.ConnectIOException: error during JRMP connection establishment; nested exception is:
        java.net.SocketTimeoutException: Read timed out

一个rmi超时。我们知道发往本地网卡的包都不会走路由器（和localhost没有区别），所以和网络关系不大。推测是因为机器load比较高（一台5g内存虚拟机跑了5个jvm）导致的。但是因为没有监控，所以不能确认。

至于为什么错误日志跑到automation.log里，看了conf/log4j.xml。类似：

<appender name="activex_appender" class="org.apache.log4j.RollingFileAppender">
        <param name="File"
                value="/home/admin/out/logs/automation_sys.log" />
        <layout class="org.apache.log4j.PatternLayout">
                <param name="ConversionPattern" value="[%d{MMdd HH:mm:ss SSS\} %-5p] [%t] %c{3\} - %m%n" />
        </layout>
</appender>
<appender name="automation_appender" class="org.apache.log4j.RollingFileAppender">
        <param name="File"
                value="/home/admin/out/logs/automation.log" />
        <layout class="org.apache.log4j.PatternLayout">
                <param name="ConversionPattern" value="[%d{MMdd HH:mm:ss SSS\} %-5p] [%t] %c{3\} - %m%n" />
        </layout>
</appender>
 
<logger name="com.alibaba.wscrosstool" additivity="false">
        <level value="info" />
        <appender-ref ref="automation_appender" />
</logger>
<root>
        <priority value ="info"/>
        <appender-ref ref="activex_appender" />
</root>

additivity="false"导致相应日志被截留在“automation_appender”里，没有放到root logger。

3、再次出错：

在申请机器，准备把应用迁出去的过程中，应用又不争气的挂了。

这次比较tricky的是，log文件夹下面出错的log统统没有。而且从某个时间点开始，所有log都蒸发了。

jstack显示应用停在每隔5s输出一个出错log的地方，结果妈的一行日志输出都没有。

因为jstat -gcutil显示还在做gc，说明程序没有死锁。无语。

到楼下跑了个步，上来重新 lsof找日志。

$/usr/sbin/lsof -p  18481 | grep -v jar$ | grep log
java    18481 admin  306w   REG             202,17 12428618   2883725 /home/admin/out/logs/automation.log.1 (deleted)
java    18481 admin  307w   REG             202,17 13431037   2883877 /home/admin/out/logs/automation_sys.log.1

发现一个被deleted的文件。

我们知道linux下面文件被删除以后，并不是立即删除的（只是标记不显示，新进程也读取不了）。只有等所有持有句柄的进程都退出之后，才会被抹去（具体可以参考鄙人的试验）。

于是福至心灵地去搜了一把怎么找回被删除的文件，按照这个帖子相当easy地找到了。

后面的错误还没有完全找出来，所以就不表了。

4、结论

log4j的配置不对害死人啊。