Am 05.02.2015 um 12:59 schrieb Hajo Locke:
Hello,
Am 05.02.2015 um 11:49 schrieb Hajo Locke:
Hello,
Am 05.02.2015 um 00:11 schrieb Seth Arnold:
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
Thanks for your effort. i ran your program on affected machine and
this is output:
CLOCK_REALTIME Thu Feb 5 10:36:40 2015
CLOCK_REALTIME_COARSE Thu Feb 5 10:36:40 2015
CLOCK_MONOTONIC Thu Feb 19 09:50:37 1970
CLOCK_MONOTONIC_COARSE Thu Feb 19 09:50:37 1970
CLOCK_MONOTONIC_RAW Thu Feb 19 09:51:01 1970
CLOCK_BOOTTIME Thu Feb 19 09:50:37 1970
CLOCK_PROCESS_CPUTIME_ID Thu Jan 1 01:00:00 1970
CLOCK_THREAD_CPUTIME_ID Thu Jan 1 01:00:00 1970
CLOCK_REALTIME - CLOCK_MONOTONIC 1418863562.991217
Current real-time is: Do 5. Feb 10:36:42 CET 2015
we do not use rsyslog, for historical reasons we use syslog-ng. I
dont know if this matters.
our systems run ntpd. In consultation with my fellows, nobody knows
about using ntpdate. while running ntpd the use of ntpdate results in
error.
The difference between CLOCK_REALTIME - CLOCK_MONOTONIC is 1:46:02
if i reload apparmor and use date-command to compare times, i see a
difference of ~ 1:38
Feb 5 13:00:05 hostname kernel: type=1400
audit(1423131731.158:8016925): apparmor...
Do 5. Feb 11:22:11 CET 2015
hmm, i cant handle these results. I can do some more tests if you want.
i have some more indications for this issue. I dont know the internals
of this kind of logging. i think dmesg itself is also affected and/or
uses same functions.
this is a sample output-line of dmesg
[4279186.720842] type=1400 audit(1423136868.774:8028551): apparmor=......
by using dmesg -T output should be human readable and already shows
wrong time:
[Do Feb 5 14:25:48 2015] type=1400 audit(1423136868.774:8028551):
apparmor=....
again 1423136868.774 ==> 12:47:48 < 1:38 < 14:25:48
I dont know if this is live calculated and may be a hint to the real
problem.
or even more basically:
echo "oddtest "`date "+%d.%m.%Y %H:%M:%S"`>/dev/kmsg
dmesg -T | grep oddtest
[Do Feb 5 16:09:03 2015] oddtest 05.02.2015 14:30:55
Oo
I dont know what this means. no virtual-servers, just real machines.
I hope this helps solve this issue.
Thanks
Thanks,
Hajo
Hajo
Hajo
--
AppArmor mailing list
[email protected]
Modify settings or unsubscribe at:
https://lists.ubuntu.com/mailman/listinfo/apparmor
