[apparmor] wrong loggingtime in apparmorlog

[John Johansen]

On 01/30/2015 12:29 PM, Christian Boltz wrote:
> Hello,
> 
> Am Freitag, 30. Januar 2015 schrieb John Johansen:
>> On 01/30/2015 12:52 AM, Hajo Locke wrote:
>>> system is Ubuntu14.04 and apparmor 2.8.95~2430-0ubuntu5.1
>>>
>>> Sometimes i see wrong time in my apparmor-logs.
>>> example: current date is "Fr 30. Jan 09:23:01 CET 2015"
>>>
>>> The apparmor-log logs these line in same moment:
>>>
>>> Jan 30 10:49:20 myhostname kernel: type=1400
>>> audit(1422606208.759:6742033): apparmor="DENIED" operation="open"
>>> .............. The timestamp 1422606208 in brackets is correct.
>>>
>>> Other logs like syslog/maillog written by syslog are ok and look
>>> normal. I think i do not something special in my apparmor-confs,
>>> just denying some binaries.
>>>
>>> audit deny /bin/programname x,
>>>
>>> After rebooting problem is gone for unknown time but will return. It
>>> seems  that difference of realtime and loggingtime increases by
>>> uptime of server.
>>>
>>> Somebody knows what happens here?
>>
>> Interesting, with the timestamp being correct, I am guessing it is
>> something to do with timezones. I'll have to dig into audit to say
>> much more. AppArmor uses the audit subsystem to do its logging, and
>> it is the audit subsystem that is handling the event time.
> 
> # date -d @1422606208.759
> Fr 30. Jan 09:23:28 CET 2015
> 
> Compared to Jan 30 10:49:20, this means an offset of 1 hour, 25 minutes 
> and 52 seconds - I wouldn't call that a typical timezone offset ;-)
> 
hrmmm, maybe. Let me revise a bit, it sounds like it something in the logic
used to convert from timestamp to date time.

Time zone logic is part of that and can do smaller increments than an hour.
That said it was just a quick guess.

> That said - I have no idea what else could be wrong :-(  - especially 
> because you wrote that your mail.log (which is also written by $syslogd) 
> contains the correct time stamp.
> 
> Are there some interesting log messages before the time difference 
> starts?
> 
Another question to ask, do the other kernel log messages exhibit the
same time stamp problem.

The apparmor logging is going to come through the kernel audit log,
if auditd is installed those messages will go through auditd instead
of syslog, without auditd they will go to the kernel ring buffer
and get pulled out with other kernel messages.

depending on how your logging is setup this message might end up
in multiple logs. The default behavior for ubuntu 14.04 is to have
apparmor messages show up in kern.log and syslog as well. Do they
show up there, do they have the same timestamp, and date time conversion?