最近syslog出了一次问题,我们配置了不同appname打印到不同文件。现在用不同appname打印log的时候,偶然会混在一起。检查过配置后,觉得不是配置问题,如果是配置问题应该每一条都会打错位置。后来同事发现是c接口线程不安全导致的。这里不是指syslog的libc接口线程不安全,是我们调用syslog的lua接口封装有问题。
syslog是一个历史悠久的日志记录标准。一般的日志记录流程是这样的:内核会在内核空间,创建好一个ring buffer,然后调用printk函数在这个buffer里进行打印。用户空间的程序要访问这个buffer,可以通过两种方式读到,一个是/proc/kmsg,另一个是sys_syslog系统调用。
内核ring buffer主要由两个程序读取:dmesg(1)和klogd(8),前者是供用户按需调用,查看内核信息,后者是从/proc/kmsg中自动读取(或者在/proc还没挂载的时候,调用sys_syslog接口读取),并转发到syslogd或者命令行,这是与内核相关的流程。
用户空间的流程主要是由syslogd(8)来处理,它会监听一些unix domain socket,比如 /dev/log(具体路径可配置),或者UDP的514端口。同时也会从klogd(8)读取日志。然后,syslogd会把这些信息打印到/log,或者通过自己的UDP协议发送到远端。具体配置在/etc/syslog.conf
用户空间的程序会调用libc函数syslog(3)来进行打印。libc会将日志打到unix domain socket: /dev/log,并由syslogd(8)来读取。
syslog(3)的接口主要用到的有openlog, syslog, closelog三个,分别是打开,关闭,和打印日志。openlog()先连接到系统logger,然后syslog接口打印日志。多线程的时候,openlog之后,还没有调syslog接口写日志,就切换到其他线程了。其他线程也调用了openlog和syslog来打印日志。切回来到原来的线程,再syslog的时候就会打印到错误的地方了。感觉openlog的接口设计也有点问题,一般是open完返回一个东西作为凭证。
解决方法有三种,一种是skynet内新建一个服务,所有日志都打到这个服务,这个服务再打印日志,相当于利用skynet的消息队列做锁保护。另一种是调整syslog参数的priority,保证不同appname对应不同priority。最后一种是直接对这个函数加锁,保证线程安全。
又及:libc的syslog接口,唯一做的就是新建,连接,写入,关闭udp socket,和自己直接做没有任何区别。对于过载,因为内核用的是ringbuffer,估计就直接覆盖前面的了。