[apparmor] wrong loggingtime in apparmorlog

[Hajo Locke]

Hello,


Am 30.01.2015 um 21:44 schrieb 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?
         no, just normal behaviour of server and logs.
>>
> 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.
     auditd itself is not installed, just libaudit-common and 
libaudit1.  (both not removeable)
>
> 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?
>
>
>
we changed ubuntu-default logging. for better overview we created a 
syslog-ng filter for apparmor and filter them in separat log.
now i commented out these lines and apparmor lines show up in syslog 
after restarting syslog-ng.
this results in a odd view, normal loglines with correct date between 
apparmor log with wrong date:

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.

What to do now?
Thanks,
Hajo