【工作笔记】syslog，kern.log大量写入invalid cookie错误信息问题

任务描述

错误出现出现过四五次，应该是诊断单元tf卡读写出问题导致下面这条告警一直高频写入到/var/log/下的syslog、kern.log、messages中

Nov 23 06:25:12 embest kernel: omap_hsmmc 48060000.mmc: [omap_hsmmc_pre_dma_transfer] invalid cookie: data->host_cookie 1 host->next_data.cookie -2107299097

等系统分区写满后WebServer（一个node.js实现的可视化系统）会卡死（也可能tf出错时就已经卡死,但是WebServer中日志中没报任何异常），只能删掉日志重启诊断单元（一个硬件设备，arm64，ubuntu系统）才能恢复，尝试重新该问题，重现不了就想办法识别该问题发生就重启诊断单元

前期思考

思路1

我在网上翻到一个有点类似的问题讨论，不确定是什么问题，有可能是板子的事，不过楼主建议“如果内核关闭SMP，或是uboot启动的时候nosmp 参数禁用SMP就不会出现该问题”https://bbs.21ic.com/icview-903274-1-1.html

所以最开始的解决方法是日志中出现这个错误就直接停止MotorServer然后重启诊断单元吧，把重启的记录也写到MotorServer.log中。

因此我完成了一个shell脚本，代码如下。

#！/bin/bash
_var=""
_var1=""
_var2=""# 判断日志文件是否存在
if [ -f /var/log/syslog ] ;then_var=`grep -w 'invalid cookie' /var/log/syslog`;
fi
if [ -f /var/log/kern.log ] ;then_var1=`grep -w 'invalid cookie' /var/log/kern.log`;
fi
if [ -f /var/log/messages ];then_var2=`grep -w 'invalid cookie' /var/log/messages`;
fi# 判断日志文件是否有'invalid cookie'相关的错误
if [[ "$_var" || "$_var1"|| "$_var2" ]];
thenecho `date +"%Y-%m-%d %H:%M:%S  MotorServer will restart because /var/log/ exist error of invalid cookie"` >> /media/eMMC-Flasher/motor/log/MotorServer.logsupervisorctl restart MotorServerecho "exist"sudo reboot
fi

我的打算是脚本执行就写到系统的定时任务，每隔12小时定时执行一次，检查/var/log下的syslog，kern.log，messages是否有invalid cookie这种错误信息，有就记录到moter-server.log，重启motor-server和诊断单元。但是并不可行，因为出现这个错误之后会不断写入，很快就满了，不能用定时任务，应该看一下syslog和kern.log有没有回调钩子

思路2

因此我也找到一个可以监听到文件事件的回调钩子函数及其相关介绍，相关参考链接如下：https://blog.csdn.net/sesiria/article/details/119721118
https://www.cnblogs.com/PikapBai/p/14480881.html

不过这个是针对所有的文件的，用这种也可行，不过效率可能没有专门针对syslog的高，但我觉得syslog、kern.log应该会提供专门的接口。

我也专门寻找了一些博客文章，发现系统日志syslog也是有提供linux内核接口，syslog.h，但是只有写入日志的接口，并没有监听写入事件的，具体了解syslog.h可以参考下面这些文章
https://blog.csdn.net/zhizhengguan/article/details/111597389
https://blog.csdn.net/u012247418/article/details/83684052
https://blog.csdn.net/qq_23274715/article/details/106138885

思路3

过滤日志，可以用syslog filter来监测是否有日志文件中的cookie invalid，从而可以过滤掉这一类的日志，从而可以防止系统日志被大量写入，磁盘空间占满。

利用rsyslog进行系统日志过滤的相关文章参考如下：
https://blog.csdn.net/FaceThePast/article/details/114483026
https://blog.csdn.net/Jailman/article/details/115956157
查看rsyslog版本：https://blog.csdn.net/jeonkc/article/details/79986634

解决方案敲定

• 初步想法：如果要根据写入syslog的内容进行判断，对诊断单元重启，目前我能想到的就是用inotify监听syslog的写入事件，然后再c++调用tail命令获取日志最新写入的前50条数据，对里面的内容进行判断是否存在“invalid cookie”错误，决定要不要重启诊断单元
• 深入思考，假如日志写入增长快，日志内容多，获取前k条的想法并不好，一来有可能出现错过漏掉的情况；就算不会出现错过漏掉的情况，假如日志内容大，写入缓存，然后利用字符串对比较，这样的效率也不好；三，syslog作为系统日志，写入会相对记录的信息相对多，同时“invalid cookie”这样的错误信息是偶发事件，并不容易复现，这样子程序则会长时间去进行无用的判断，浪费系统资源。
• 优化后最终决策：syslog filter过滤出cookie invalid再触发inotify，只要触发了就重启，不用传递日志内容。设置rsyslog规则，把包含cookie invalid的日志信息写入一个A文件，inotify就监听A文件，A文件有写入事件了就重启。
  这样子做，一来是保留了错误日志信息，也方便监听，而且inotify的c++程序可以挂在后台supervisor进程，同时偶发事件不占用程序一直判断。

实现过程

配置rsyslog过滤包含“invalid error”的日志

（1）这一步我们的想法是写过滤规则，将包含指定内容的日志信息写入自定义的文件。在根据https://blog.csdn.net/FaceThePast/article/details/114483026 博客里面的方式设置rsylog.conf，但是发现并不生效。
（2）后面查了其他博客，例如https://blog.csdn.net/Jailman/article/details/115956157。发现不同版本的rsyslog服务是的配置文件有一些不同，可以用下面命令去查看版本

 rsyslogd -ver

图片上面看是V8的，格式差不多是下面这样，但是下面这个的意思是，日志内容与keyword相等的就停止写入，并且修改了内容后要重启reyslog

这不符合我们的要求，那我们参考v7的，写成这样，意思是将包含invalid cookie内容的日志写入/var/log/invalid_cookie_error.log文件中

syslog.conf
:rawmsg, contains, "invalid cookie" /var/log/invalid_cookie_error.log

然后将写好的过滤规则文件syslog.conf放到/etc/rsyslog.d/目录下，因为规则文件存放的路径是/etc/rsyslog.conf里面原来配置好的

最后重启服务

service rsyslog restart

还要看看服务有没有正常运行,有没有错误信息

service rsyslog status

invotify监听指定文件是否被写入

这里附上invotify监听的c++代码

#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <unistd.h>
#include <errno.h>
#include <sys/inotify.h>
#include <sys/reboot.h>
#include <iostream>
#include <sys/time.h>
using namespace std;
#define EVENT_NUM  12
void GetTime(string& strtime)
{time_t tt = time(NULL);//这句返回的只是一个时间cuotm* t = localtime(&tt);char buffer[50];snprintf(buffer, sizeof(buffer), "%04d-%02d-%02d %02d:%02d:%02d", t->tm_year + 1900, t->tm_mon + 1, t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec);strtime.append(buffer);
}string GetTime()
{string strtime;GetTime(strtime);return strtime;
}
const char *event_str[EVENT_NUM] =
{"IN_ACCESS","IN_MODIFY","IN_ATTRIB","IN_CLOSE_WRITE","IN_CLOSE_NOWRITE","IN_OPEN","IN_MOVED_FROM","IN_MOVED_TO","IN_CREATE","IN_DELETE","IN_DELETE_SELF","IN_MOVE_SELF"
};int inotifyTask(char *argv[]) 
{cout<<GetTime().c_str()<<":inotify event start....."<<endl;int fd = -1;fd = inotify_init();int wd1 = -1;struct inotify_event *event;int length;int nread;char buf[BUFSIZ];int i = 0;buf[sizeof(buf) - 1] = 0;wd1 = inotify_add_watch(fd, argv[1], IN_ALL_EVENTS);if(wd1 < 0){fprintf(stderr, "%s:inotify_add_watch %s failed\n", GetTime().c_str(),argv[1]);printf("%s:Error no.%d: %s\n", GetTime().c_str(),errno, strerror(errno));}length = read(fd, buf, sizeof(buf) - 1);nread = 0;// inotify 事件发生时while(length > 0){printf("\n");event = (struct inotify_event *)&buf[nread];// 遍历所有事件for(i = 0; i< EVENT_NUM; i++){			// 判断事件是否发生if( (event->mask >> i) & 1 ){	// 该监控项为目录或目录下的文件时if(event->len > 0){fprintf(stdout, "%s:%s --- %s\n",GetTime().c_str(), event->name, event_str[i]);}// 该监控项为文件时else if(event->len == 0){if(event->wd == wd1){if(strcmp(event_str[i],"IN_MODIFY")==0){fprintf(stdout, "%s:%s --- %s\n",GetTime().c_str(), argv[1], event_str[i]);system("echo `date +\"%Y-%m-%d %H:%M:%S  MotorServer will restart because /var/log/ exist error of invalid cookie\"` >> /media/eMMC-Flasher/motor/log/MotorServer.log");system("nice -n 19 supervisorctl stop MotorServer");system("nice -n 19 supervisorctl stop WebServer");sync(); //  同步磁盘数据,将缓存数据回写到硬盘,以防数据丢失[luther.gliethttp]printf("%s:system will reboot\n",GetTime().c_str());return system("sudo reboot");// return reboot(RB_AUTOBOOT);}}}}}nread = nread + sizeof(struct inotify_event) + event->len;length = length - sizeof(struct inotify_event) - event->len;}close(fd);return 0;
}int main(int argc, char *argv[])
{	if(argc < 2){fprintf(stderr, "Usage: %s path\n", argv[0]);return -1;}if(inotifyTask(argv) == -1){return -1;}return 0;
}

• 在linux中可以用logger "xxx"模拟将日志信息写入syslog

logger "embest kernel: omap_hsmmc 48060000.mmc: [omap_hsmmc_pre_dma_transfer] invalid cookie: data->host_cookie 1 host->next_data.cookie -2107299097"