[apparmor] wrong loggingtime in apparmorlog

Hajo Locke Hajo.Locke at gmx.de
Thu Feb 5 11:59:46 UTC 2015


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.


>
>>
>> I hope this helps solve this issue.
>>
>> Thanks
>
> Thanks,
> Hajo 


Hajo




More information about the AppArmor mailing list