On Wed, Feb 04, 2015 at 10:47:58AM +0100, Hajo Locke wrote: > Feb 4 09:55:01 hostname CRON[3898]: (root)... > Feb 4 11:30:50 hostname kernel: type=1400 > audit(1423040101.577:7785293): apparmor="DENIED"... > Feb 4 09:55:01 hostname CRON[3911]: (root)... > > a relation to audit seems possible. i found more kernel loglines in > syslog with wrong date which are not in direct relation to apparmor. > i think complete kern.log is wrong. > may be more kernel related? we upgrade regularly, current version > on this machine is 3.13.0-43-generic (Ubuntu 14.04 LTS) > Currently only rebooting solves this problem. after reboot > timestamps in loglines are identical. But by increasing uptime the > difference between realtime and kernel-log-time grows. > one server with uptime ~2 days has kernel-time 53 seconds in future > (3.13.0-45-generic). server from loglines above has uptime 48 days > and difference is more than 1,5 hours.
I've got a theory that's not very well thought through yet; to be honest, this is an interesting problem that I've never seen before. Here's some source code that's very similar to the rsyslog daemon used in Ubuntu 14.04 LTS: http://sources.debian.net/src/rsyslog/7.4.8-1%7Ebpo70%2B1/plugins/imklog/bsd.c/#L58 Note this section: /* ... */ clock_gettime(CLOCK_MONOTONIC, &monotonic); clock_gettime(CLOCK_REALTIME, &realtime); secOffs = realtime.tv_sec - monotonic.tv_sec; usecOffs = (realtime.tv_nsec - monotonic.tv_nsec) / 1000; if(usecOffs < 0) { secOffs--; usecOffs += 1000000l; } usecs += usecOffs; if(usecs > 999999l) { secs++; usecs -= 1000000l; } secs += secOffs; tv.tv_sec = secs; tv.tv_usec = usecs; tp = &tv; done: Syslog(pri, buf, tp); /* ... */ rsyslog is changing the timestamp supplied to its internal Syslog() routine based on the time difference between the CLOCK_MONOTONIC and CLOCK_REALTIME clocks. The CLOCK_MONOTONIC clock will only ever move forward, while CLOCK_REALTIME can jump backwards if e.g. ntpdate(8) or date(1) sets an entirely new time. So, my theory -- this system is using ntpdate(8) in a cronjob to set the time rather than using ntpd(8), which would _skew_ the time in a fashion that's more amenable to keeping CLOCK_MONOTONIC and CLOCK_REALTIME closer to synchronized. (ntpd(8) can ask the system clock to speed up or slow down so that seconds take more or less time, but when skewing it won't jump the time forwards or backwards abruptly.) I've attached a little program that will output all the clocks documented in clock_gettime(3) as well as the difference between the MONOTONIC clock and REALTIME clock. If you've installed build-essential, you should be able to compile it and run with just "make clocks ; ./clocks". If I'm correct, the difference between the MONOTONIC and the REALTIME clock will get worse over the uptime of the system. And if I'm correct, you can fix the issue by switching to ntpd rather than using ntpdate periodically. You may also be able to use the klogParseKernelTimestamp configuration variable from rsyslog: http://www.rsyslog.com/doc/master/configuration/modules/imklog.html I hope this helps solve this issue. Thanks
#include <time.h>
#include <stdio.h>
int main(int argc, char* argv[]) {
struct timespec realtime, real_coarse, monotonic, mono_coarse,
mono_raw, boottime, process_cputime_id,
thread_cputime_id;
int ret;
time_t t;
ret = clock_gettime(CLOCK_REALTIME, &realtime);
if (ret) perror("CLOCK_REALTIME");
ret = clock_gettime(CLOCK_REALTIME_COARSE, &real_coarse);
if (ret) perror("CLOCK_REALTIME_COARSE");
ret = clock_gettime(CLOCK_MONOTONIC, &monotonic);
if (ret) perror("CLOCK_MONOTONIC");
ret = clock_gettime(CLOCK_MONOTONIC_COARSE, &mono_coarse);
if (ret) perror("CLOCK_MONOTONIC_COARSE");
ret = clock_gettime(CLOCK_MONOTONIC_RAW, &mono_raw);
if (ret) perror("CLOCK_MONOTONIC_RAW");
ret = clock_gettime(CLOCK_BOOTTIME, &boottime);
if (ret) perror("CLOCK_BOOTTIME");
ret = clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &process_cputime_id);
if (ret) perror("CLOCK_PROCESS_CPUTIME_ID");
ret = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &thread_cputime_id);
if (ret) perror("CLOCK_THREAD_CPUTIME_ID");
t=realtime.tv_sec;
printf("%25s %s", "CLOCK_REALTIME", ctime(&t));
t=real_coarse.tv_sec;
printf("%25s %s", "CLOCK_REALTIME_COARSE", ctime(&t));
t=monotonic.tv_sec;
printf("%25s %s", "CLOCK_MONOTONIC", ctime(&t));
t=mono_coarse.tv_sec;
printf("%25s %s", "CLOCK_MONOTONIC_COARSE", ctime(&t));
t=mono_raw.tv_sec;
printf("%25s %s", "CLOCK_MONOTONIC_RAW", ctime(&t));
t=boottime.tv_sec;
printf("%25s %s", "CLOCK_BOOTTIME", ctime(&t));
t=process_cputime_id.tv_sec;
printf("%25s %s", "CLOCK_PROCESS_CPUTIME_ID", ctime(&t));
t=thread_cputime_id.tv_sec;
printf("%25s %s", "CLOCK_THREAD_CPUTIME_ID", ctime(&t));
long secOffs, nsecOffs;
secOffs = realtime.tv_sec - monotonic.tv_sec;
nsecOffs = realtime.tv_nsec - monotonic.tv_nsec;
long double d;
if(nsecOffs < 0) {
secOffs--;
nsecOffs += 1000000000l;
} else if (nsecOffs > 999999999l) {
secOffs++;
nsecOffs -= 1000000000l;
}
d = (long double)nsecOffs / 1000000000l;
d += secOffs;
printf("CLOCK_REALTIME - CLOCK_MONOTONIC %LF\n", d);
return 0;
}
signature.asc
Description: Digital signature
-- AppArmor mailing list [email protected] Modify settings or unsubscribe at: https://lists.ubuntu.com/mailman/listinfo/apparmor
