[apparmor] wrong loggingtime in apparmorlog

Thu Feb 5 13:35:53 UTC 2015

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