Linux 6中Cachefilesd服务过量日志问题解决

郑全

我们在实际运维环境中，对操作系统OS的维护是必须进行的。应用系统是一个整体，绝对不仅仅包括应用服务器上运行的应用程序本身和数据库服务器，还包括操作系统、网络、存储甚至硬件方面。对应用系统整体的监控保障，才能带来最稳定的运行性能。
 
绝大多数情况下，我们环境中的操作系统都是可以持续运行的，不会引起大的问题。一旦出现当机、服务器Hange住的情况，就可能导致灾难性的结果。所以，亡羊补牢不如防微杜渐，经常性的查看系统运行情况，查看磁盘空间、CPU使用率和各种日志信息，都可以尽早帮助我们解决操作系统层面问题。
 
本篇介绍一个简单的Linux进程Bug解决问题。

　　1、问题介绍

　　一个接受的新系统，应用服务器和数据库服务器均为Linux 6版本。系统本身架构比较简单，而且运行一年来也没有什么严重故障发生。

　　[root@TESTDB ~]# uname -r

　　2.6.32-131.0.15.el6.x86_64

　　[root@TESTDB ~]# cat /etc/RedHat-release

　　Red Hat Enterprise Linux Server release 6.1 (Santiago)

　　[root@TESTDB ~]# uptime

　　11:28:14 up 66 days, 21:31,  1 user,  load average: 0.50, 0.44, 0.37 –有例行关机维护

　　Linux环境中，最常见日志为/var/log目录，检查message是我们直接的日志检查策略。

　　[root@TESTDB ~]# tail -n 10 /var/log/messages

　　Mar 26 08:31:42 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:32:12 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:32:42 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:33:12 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:33:42 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:34:12 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:34:42 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:35:12 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:35:42 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:36:12 TESTDB cachefilesd[1591]: Scan complete

　　日志量很大，从每周自动归档情况看，日志总量大已经持续比较长时间了。

　　[root@TESTDB ~]# cd /var/log/

　　[root@TESTDB log]# ls -l | grep message

　　-rw-------. 1 root        root        549637 Mar 26 08:55 messages

　　-rw-------. 1 root        root        1193545 Mar  2 03:31 messages-20140302

　　-rw-------. 1 root        root        1191893 Mar  9 03:16 messages-20140309

　　-rw-------. 1 root        root        1194902 Mar 16 03:27 messages-20140316

　　-rw-------. 1 root        root        1195079 Mar 23 03:39 messages-20140323

　　从日志上看，服务进程cachefilesd在每隔30s，自动写入一条记录。除了日志过多冗余条目外，没有其他问题爆出。

　　message信息本身是中性的，通知调错类信息。过于频繁的正常信息在其中，是容易将错误内容淹没其中的。所以期望还是可以加以解决。

　　2、故障分析

　　我们遇到的故障错误是分种类的。一个极端是紧急严重，比如操作系统宕机、hang住无响应，直接影响业务运行，甚至数据丢失。另一个极端就是一些短期不会引起大问题的“小故障”。紧急严重错误考验的是运维人员的知识、经验和心理素质，而小故障考验的职业精神和专业素质。
 
对于这个问题，笔者也没有什么很好地思路，只有求助官方资料库。在Red Hat官网的客户订阅中，笔者找到了文章《Why server is flodded with `cachefilesd Scan complete` messages?》其中描述了相同的问题。
 
Cachefilesd进程是负责进行网络文件系统的文件和目录缓存管理的，比如AFS和NFS这类网络文件系统，需要在本地系统中存在一个Cache对象。这个问题是由于cachefilesd服务自身的bug造成的，由于内部设置了错误的日志级别（log level）。所以每次cachefilesd在工作进行Scan的时候，都会写入到/var/log/messages日志文件里面。
 
这个问题已经被Red Hat列入为Bug，编号为680127。cachefilesd是作为操作系统的一个后台服务进行工作的。当'/var/cache/fscache/cache'为空的的时候，就会自动将Scan Completed信息写入到日志中。
 
根据频率，每分钟会进行两条日志的写入。这个和我们实际系统的情况相符合。

　　版本是Linux 6，cachefilesd包版本为0.10.1-2。查看当前系统版本情况。

　　[root@TESTDB ~]# rpm -qa | grep cachefilesd

　　cachefilesd-0.10.1-2.el6.x86_64

　　修复方法是将cachefilesd版本升级到最新版本，就可以避免问题出现。

　　3、问题解决

　　定位到了问题，解决策略就是升级cachefilesd包。从官方网站上搜索专门的rpm包下载，目录如下：

　　下载最新的版本0.10.2.1。使用rpm进行安装。

　　[root@TESTDB ~]# cd /

　　[root@TESTDB /]# mkdir updates

　　[root@TESTDB /]# cd updates

　　[root@TESTDB updates]# ls -l

　　total 36

　　-rw-r--r--. 1 root root 35332 Mar 26 08:52 cachefilesd-0.10.2-1.el6.x86_64.rpm

　　参数-Uvh会去自己判断当前版本情况，如果是没有对应程序就直接安装，否则就进入升级模式。

　　[root@TESTDB updates]# rpm -Uvh cachefilesd-0.10.2-1.el6.x86_64.rpm

　　warning: cachefilesd-0.10.2-1.el6.x86_64.rpm: Header V3 RSA/SHA256 Signature, key ID fd431d51: NOKEY
 
Preparing...                ########################################### [100%]

　　1:cachefilesd            ########################################### [100%]

　　最后检查效果，日志中包括了cachefilesd服务终止重启的过程。重启之后，就再没有新日志项目产生。

　　Mar 26 08:55:12 TESTDB cachefilesd[1591]: Scan complete

　　Mar 26 08:55:21 TESTDB cachefilesd[1591]: Daemon Terminated

　　Mar 26 08:55:21 TESTDB kernel: CacheFiles: File cache on sda3 unregistering

　　Mar 26 08:55:21 TESTDB kernel: FS-Cache: Withdrawing cache "mycache"

　　Mar 26 08:55:21 TESTDB cachefilesd[10518]: About to bind cache

　　Mar 26 08:55:21 TESTDB cachefilesd[10518]: Bound cache

　　Mar 26 08:55:21 TESTDB kernel: FS-Cache: Cache "mycache" added (type cachefiles)
 
Mar 26 08:55:21 TESTDB kernel: CacheFiles: File cache on sda3 registered

　　Mar 26 08:55:21 TESTDB cachefilesd[10519]: Daemon Started

　　作为服务的cachefilesd，也工作正常。

　　[root@TESTDB ~]# service cachefilesd status

　　cachefilesd (pid  10519) is running...

　　[root@TESTDB ~]# chkconfig --list cachefilesd

　　cachefilesd    0:off  1:off  2:on    3:on    4:on    5:on    6:off

　　故障解决。

　　4、结论

　　在实际运维环境中，各种故障都是可能发生的。而且诊断问题、解决问题需要很多经验的积累和总结。及时发现问题、防微杜渐是保障系统持续健康运行的最好保障。“救火队员”不如“老黄牛”，也就是这个道理。