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
--
AppArmor mailing list
[email protected]
Modify settings or unsubscribe at:
https://lists.ubuntu.com/mailman/listinfo/apparmor
