YANGHONG

`/var/log/kern.log' Races with `/var/log/messages'

我已经花了累计一整周的时间在这个事情上了,虽然比起原来断断续续 De 了两个月的 bug ,这个可能算不上什么。

问题

我修改了 KVM ,在 exit 的处理函数里填了一些判断代码和打印代码,用的就是 printk(KERN_INFO "...") 这种老土的方法。只不过我在一次 exit 的前后有两次打印,类似于

static unsigned long start_count = 0;
static unsigned long end_count = 0;
/* ... */
static int vcpu_enter_guest(struct kvm_vcpu *vcpu)
{
        /* ... */
        start_count++;
        printk(KERN_INFO "[%d:%d] start\n", start_count, end_count);
        /* ... */
        end_count++;
        printk(KERN_INFO "[%d:%d] end\n", start_count, end_count);
        /* ... */
}

我用 sudo tail -f /var/log/kern.log 来观察打印信息,这样问题就来了。按理说我应该能看到的输出是

[1:0]
[1:1]
[2:1]
[2:2]
[3:2]
[3:3]

但是实际上我能看到的输出是

[1:0]
[2:1]
[3:2]
[4:3]
[5:4]

总结来说,我只能看到 log 的一部分。关于配置,系统是 Gentoo ,syslog 用的是 syslog-ng , /etc/syslog-ng/syslog-ng.conf 如下

source src { system(); internal(); };
source kernsrc { file("/proc/kmsg"); }; # -------- for kern.log

destination syslog { file("var/log/syslog"); };
destination kern { file("/var/log/kern.log"); }; # -------- for kern.log
destination messages { file("/var/log/messages"); }; # -------- default

# By default messages are logged to tty12...
destination console_all { file("/dev/tty12"); };
# ...if you intend to use /dev/console for programs like xconsole
# you can comment out the destination line above that references /dev/tty12
# and uncomment the line below.
#destination console_all { file("/dev/console"); };

# filter f_kern { facility(kern); };

log { source(src); destination(messages); }; # -------- default
log { source(src); destination(console_all); };
log { source(kernsrc); destination(kern); }; # -------- for kern.log

Gentoo 的 syslog-ng 默认的日志文件只有 /var/log/messages ,如果需要 kern.log 需要手动添加。

原因

一开始,我以为是我没有处理好中断的问题,因为这个 bug 在更之前的一周由于我在关中断的环境中调用了某个 driver function ,导致系统 crash 。这次我本以为也是因为没处理好中断,导致 printk 的顺序出现问题。所以我特地在所有可能涉及到 flag 检查顺序和 print 的前后都先关中断后开中断。但是问题并没有解决。

然后我在想会不会是我实现逻辑上有问题,因为实际代码比上面的复杂得多,有好几个 flag 需要判断,而这个时候中断是开启的,所以无法保证 nested interrupt 不会引起没想到的问题。因此,上一周整整一周,我都把精力花在思考怎样的中断顺序会出问题,以及加上 spinlock 我也试过了,依然得不到想要的输出。

今天,碰巧我觉得积攒了一个星期的 kern.logmessages 好几百兆的文件有点不爽,折腾了下 logrotatecron 来定期压缩这些日志。这个时候我突然有个想法:其实 kern.log 按理说应该是 messages 的内容的子集,要不比较一下这两个文件?其实这种想法也就是这么一想,估计应该是徒劳的。但是当我一比较两个文件,简直就是眼泪掉下来啊:

--- /var/log/kern.log ---
[1:0]
[2:1]
[3:2]
[4:3]
...
--- /var/log/messages ---
[1:1]
[2:2]
[3:3]
[4:4]
...

居然!经过我多次测试,发现所有记录并不是恰好一个间隔一个地分布在两个日志文件,的确有些连续记录会在同一个文件里,而且也只有在我打印的这部分出现了这种 interleaving 的情况。但是为啥呢,我明明是在一个函数的前后调用了两次 printk ,结果却打印在了本应该一致的两个文件里。

解决

暂时还没想出什么好办法。如果只用 /var/log/messages 的话,里面有太多 pam_unix 的无聊的打印干扰视线;如果只用 /var/log/kern.log 则会有问题。暂时打算先看一下 klogd 是不是能用。

Update

目前解决方法是 syslog-ngsysklogd 共存。同时跑两个 syslog 感觉有点蛋疼, syslog-ng 现在只负责 /var/log/messagessysklogd 负责其他的文件,现在看起来好像没有问题。关于 syslog-ng 的配置,我还有一点比较在意,就是在 options 里面,有一条 threaded(yes) ,会不会有些问题呢这里?

comments powered by Disqus