前几天内部网络设备集中认证审计系统tacacsGUI系统的远程数据库服务器突然宕机,重新启动数据库服务器后发现新数据一直无法入库,今天抽空对源码进行了分析,顺利解决故障,将故障解决思路及过程记录如下:
一、处理思路
分析代码了解tacacsGUI系统的入库原理,找出入库文件源码,对入库源码分析后判断是解析故障还是数据库故障,根据故障实际情况进行处理。
tacacsGUI系统通过parseTacLog.sh文件启动入库,该shell每隔60秒处理一次tacacs生成的原始日志文件tac_plus.acct,通过比较最后一行的内容确定文件是否有更新,如果有更新就将文件内容拷贝生成一个tac_acc.temp临时文件,拷贝完成后通过/var/www/tacacs/parserMain.php文件对tac_acc.temp文件内容进行解析并将解析后的结果拼凑成INSERT语句插入至数据库中。
二、处理过程
1、首先要定位找到处理日志入库的源码文件;
ps -ef | grep tacacs
root 1573 1 0 2018 ? 00:00:00 /usr/sbin/in.tftpd --listen --user tftp --address 0.0.0.0:69 --secure /var/www/tacacs/backup
root 4889 1 0 2018 ? 00:03:46 /usr/sbin/tac_plus -C /etc/tacacs+/tac_plus.conf
www-data 10603 1 0 15:27 ? 00:00:01 /bin/bash /var/www/tacacs/parseTacLog.sh
第一步找到入库shell文件
2、分析入库parseTacLog.sh文件找出入库解析文件parserMain.php;
while :
do
LASTLINETEMP="$(sed -e '$!d' /var/log/tac_acc.temp)"
if [[ $LASTLINETEMP == "" ]] || [[ $LASTLINETEMP == " " ]] ; then
echo "NO"
cp /var/log/tac_plus.acct /var/log/tac_acc.temp
echo 'copied!'
/usr/bin/php /var/www/tacacs/parserMain.php
else
echo "yes"
LASTLINETEMP="$(sed -e '$!d' /var/log/tac_acc.temp)"
LASTLINEACTUAL="$(sed -e '$!d' /var/log/tac_plus.acct)"
if [[ $LASTLINETEMP == $LASTLINEACTUAL ]] ; then
echo "Without Update"
else
LASTLINETEMP2="$(echo $LASTLINETEMP | sed -e's/ */.*/g')"
LASTLINENUM="$(grep -nr $LASTLINETEMP2 /var/log/tac_plus.acct | awk -F ':' '{print $1}')"
echo "Copy From Line $LASTLINENUM"
tail --lines=+$LASTLINENUM /var/log/tac_plus.acct > /var/log/tac_acc.temp
echo "Copied"
/usr/bin/php /var/www/tacacs/parserMain.php
fi
fi
sleep 60
done
3、直接执行入库解析文件parserMain.php,观察输出信息,判断故障点
直接在命令行下执行 /usr/bin/php /var/www/tacacs/parserMain.php
下面的结果我已经精简过了,观察最后一行加粗显示的单词。
Number of lines: 7</br></br>Jan 21 15:29:24 172.56.111.2 xfdxvip unknown 172.63.255.6 start task_id=0 timezone=8 service=shell protocol=telnet</br>Correct Date: 2019:01:21 15:29:24</br>Unix Time stamp: 1548055764</br>Device IP: 172.56.111.2</br>User IP: 172.63.255.6</br>Username: xfdxvip</br>Start Session: Yes.</br>line wrote</br></br>Jan 21 15:29:49 172.56.111.2 xfdxvip unknown 172.63.255.6 stop task_id=0 timezone=8 service=shell disc-cause=1 disc-cause-ext=1022 bytes_in=0 bytes_out=0 paks_in=0 paks_out=0 elapsed_time=24</br>Correct Date: 2019:01:21 15:29:49</br>Unix Time stamp: 1548055789</br>Device IP: 172.56.111.2</br>User IP: 172.63.255.6</br>Username: xfdxvip</br>line wrote</br></br></br>No Matches :( </br></br>
分析入库解析文件parserMain.php,找出故障原因
//WRITE TO DB START
include ('/var/www/lp.php');
$conn = new mysqli($hn, $un, $pw, $db);
if ($conn->connect_error) die($conn->connect_error);
if ($CMDval!='') $session='';
$query="INSERT INTO tac_accouting (ID, unixdate, ipaddrNameDev, ipaddrUser, username, session, privilege, cmd, fullline)".
" VALUES (NULL, '".$unixtime."', '".$deviceIP."', '".$userIP."', '".$username."',".
"'".$session."', '".$privilegeLVLval."', '".$CMDval."', '".$loglineArray[$x]."')";
$conn->query($query);
echo 'line wrote</br>';
//WRITE TO DB END
}
else {echo 'No Matches :( </br>';}
echo '</br>';
源文件很长,我只抽取了最后入库部分,观察前面的输出发现,日志中已经执行过入库过程,只是结果没有成功,但是有没有报错信息,所以定位这次故障源在数据库。
4、修改入库源文件,打印生成入库sql语句
//WRITE TO DB START
include ('/var/www/lp.php');
$conn = new mysqli($hn, $un, $pw, $db);
if ($conn->connect_error) die($conn->connect_error);
if ($CMDval!='') $session='';
$query="INSERT INTO tac_accouting (ID, unixdate, ipaddrNameDev, ipaddrUser, username, session, privilege, cmd, fullline)".
" VALUES (NULL, '".$unixtime."', '".$deviceIP."', '".$userIP."', '".$username."',".
"'".$session."', '".$privilegeLVLval."', '".$CMDval."', '".$loglineArray[$x]."')";
echo $query;
$conn->query($query);
echo 'line wrote</br>';
//WRITE TO DB END
只需要在执行入库语句前加入一句echo $query即可,保持退出后再次执行入库命令/usr/bin/php /var/www/tacacs/parserMain.php
观察输出情况
Correct Date: 2019:01:21 15:29:49</br>Unix Time stamp: 1548055789</br>Device IP: 172.56.111.2</br>User IP: 172.63.255.6</br>Username: xfdxvip</br>INSERT INTO tac_accouting (ID, unixdate, ipaddrNameDev, ipaddrUser, username, session, privilege, cmd, fullline) VALUES (NULL, '1548055789', '172.56.111.2', '172.63.255.6', 'xfdxvip','', '', '', 'Jan 21 15:29:49 172.56.111.2 xfdxvip unknown 172.63.255.6 stoptask_id=0 timezone=8 service=shell disc-cause=1 disc-cause-ext=1022 bytes_in=0 bytes_out=0 paks_in=0 paks_out=0 elapsed_time=24')line wrote</br></br>No Matches :( </br></br>
5、复制上一步加粗的sql语句手工在数据库中执行观察输出
发现真正的问题是入库表的主键ID冲突,导致插入数据失败,我们手工查看一下83967这个ID是否存在;
mysql> select * from tac_accouting where id='83967';
Empty set (0.00 sec)
发现这个ID并不存在,这个主键冲突好奇怪,应该是mysql异常退出后的bug。
查看表的定义如下
原来当前系统已经将最后一个自动更新的数值定位成83967
6、解决问题思路,手工入库上一条失败记录,将ID项不由mysql系统生成而是手工填入一个大于83967的数字
INSERT INTO tac_accouting (ID, unixdate, ipaddrNameDev, ipaddrUser, username, session, privilege, cmd, fullline) VALUES (83969, '1548sk_id=0 timezone=8 service=shell disc-cause=1 disc-cause-ext=1022 bytes_in=0 bytes_out=0 paks_in=0 paks_out=0 elapsed_time=24'); service=shell disc-cause=1 disc-cause-ext=1022 bytes_in=0 bytes_out=0 paks_in=0 paks_outQuery OK, 1 row affected (0.01 sec)
7、再次观察数据表入库情况,发现完全恢复正常
间隔几分钟后发现数据库中已经新增了50条新纪录。
8、登录图形界面确认是否恢复
1、发现原来的数据断点在1月2日,新入库时间是1月21日,这个是系统登录记录
2、下面的是系统操作记录,发现操作记录也都恢复了正常记录,可以把操作记录全部记录在数据库中并正常查看。
三、故障总结
处理这类故障无非是解析字符串故障或者数据库入库失败,分析时注意打印输出日志,通过分析输出日志定位故障,处理数据库故障时建议最好手工登录将程序生成的sql语句粘贴进行手工执行,在这个过程中可以获得更多的有价值信息,这个故障应该是mysql数据库服务器异常宕机后导致的数据不一致bug,对于数据库异常宕机应用系统或多或少会出现一些不正常,尽量应该避免出现数据库服务器异常宕机。