又一个无辜的故障排查

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

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



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的配置不对害死人啊。



  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值