如何在Linux 6中解决Cachefilesd服务过量日志

一个接受的新系统，应用服务器和数据库服务器均为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信息本身是中性的，通知调错类信息。过于频繁的正常信息在其中，是容易将错误内容淹没其中的。所以期望还是可以加以解决。

我们遇到的故障错误是分种类的。一个极端是紧急严重，比如操作系统宕机、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版本升级到最新版本，就可以避免问题出现。

定位到了问题，解决策略就是升级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: NOKEYPreparing... ########################################### [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

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