Corrupted AppArmor audit log messages

[Vajra Vrtti]

Binary package hint: apparmor

AppArmor is writing corrupted audit messages to /var/log/messages, which crashes the aa-logprof tool.

The attached file contains the console output of a aa-genprof run and the corrupted messages selected by visual inspection of /var/log/messages. After copying /var/log/messages, and deleting the messages listed in the attachment, aa-logprof was successfully executed using the clean log file.

My system is a fresh install of Ubuntu 7.10. My sources.list only contains the Ubuntu, Medibuntu and Canonical repositories, and all software was installed from them, with the sole exception of TrueCrypt, which was installed from the Gutsy .deb file available at www.truecrypt.org.

[Vajra Vrtti (vajravrtti)]

I don't know why the attached file isn't correctly displayed in my browser.
But it's OK if you save and open it in a test editor.

[John Johansen (jjohansen)]

The log isn't displaying correctly in the browser because its type is set as html, but it is a plain text file.

The log is corrupt but in a very odd way that I have never encountered before. I have a few possible ideas:

Your kernel ring buffer is being filled and the messages are wrapping, overwriting previous messages, this is a known problem with messages going to the ring buffer and is fixed by using the audit daemon. This can't be the sole cause of the problem because its not an occasional message being split but many messages with many repeated characters.

Most of the information seems to be intact but has sever "studdering", with sporadic other bits of information. The "studdering" seems to be caused by the interleaving of the same message several times. This would get caused by either having multiple sources writting the same message to the same destination (unlikely) or possibly an application bug where a small part of a buffer gets written and then fails, and the application retries writing the buffer, for this to happen the application would have to be mishandling the return code.

Your specific log output looks like it has both problems happening, I have to assume that the problem is occuring somewhere in the audit -> kern buffer -> dd -> ksyslogd -> syslog chain. I can pretty confidently rule out the AppArmor module as it builds up each message in a buffer and either logs it as a whole or fails the whole message.

If this is a reoccurring problem we can track down where it is happening by cutting out parts of the auditing chain. Basically try sending the dd output straight to disk, if that is corrupt then its either kernel audit or dd, to rule out dd we would remove dd and have ksyslogd read the ring buffer directly, etc.

[Mathias Gug (mathiaz)]

On Thu, Nov 08, 2007 at 04:45:03PM -0000, John Johansen wrote:
> Your specific log output looks like it has both problems happening, I
> have to assume that the problem is occuring somewhere in the audit ->
> kern buffer -> dd -> ksyslogd -> syslog chain.

Another solution might be to install the auditd daemon, so that apparmor
messages are not sent to the syslog system. You can find the audit
package in the universe repository.

  status incomplete

[Vajra Vrtti (vajravrtti)]

Before each of the following tests I deleted /etc/apparmor.d/usr.bin.skype and reloaded all apparmor profiles.

First, I ran “aa-genprof skype”. This time there was only one corrupted message in /var/log/messages (attachment). Although it issued some error messages, the process did not crash, and the profile was correctly created.

Second, I installed the auditd package, as suggested, and then “aa-genprof skype” ran perfectly using /var/log/audit/audit.log.

I will try to profile more complex applications, such as Firefox, and post the results here.

[Vajra Vrtti (vajravrtti)]

I was able to successfully create a very complete AppArmor profile for Firefox using several passes of aa-logprof.
No corrupted messages were written to /var/log/audit/audit.log.

[Vajra Vrtti (vajravrtti)]

>If this is a reoccurring problem we can track down where it is happening by cutting out parts of the auditing chain.
> Basically try sending the dd output straight to disk, if that is corrupt then its either kernel audit or dd, to rule out
>dd we would remove dd and have ksyslogd read the ring buffer directly, etc.

I'm afraid this is beyond my technical skill.

[John Johansen (jjohansen)]

If auditd is working for you, I wouldn't worry about it.

If however you want to use syslog or just want to try debugging this I can walk you through it step by step. It really wouldn't be much more than copying and pasting some script lines and commenting others out.

[Vajra Vrtti (vajravrtti)]

@John Johansen

Although auditd is working fine for me, I think we could try to debug this. I have a test system where I can do that without problems, if you tell me what to do.

[Vajra Vrtti (vajravrtti)]

@John Johansen

I uninstalled the auditd package, deleted the skype profile from AppArmor, and ran aa-genprof again to check if the problem could be recreated. I got a corrupted message again.

[John Johansen (jjohansen)]

okay the first thing I want you to try is removing the use of dd from the auditing chain

open /etc/init.d/klogd in an editor (you need to be root), find the line that looks like this

    # shovel /proc/kmsg to pipe readable by klogd user
    start-stop-daemon --start --pidfile $kmsgpidfile --exec /bin/dd -b -m -- bs=1 if=/proc/kmsg of=$kmsgpipe

and comment it out so it is now

    # shovel /proc/kmsg to pipe readable by klogd user
# start-stop-daemon --start --pidfile $kmsgpidfile --exec /bin/dd -b -m -- bs=1 if=/proc/kmsg of=$kmsgpipe

now find the line

    # start klogd as non-root with reading from kmsgpipe
    start-stop-daemon --start --quiet --chuid klog --exec $binpath -- $KLOGD

and comment it out and replace it with the command shown below

    # start klogd as non-root with reading from kmsgpipe
# start-stop-daemon --start --quiet --chuid klog --exec $binpath -- $KLOGD
    start-stop-daemon --start --quiet --exec $binpath -- /proc/kmsg

save /etc/init.d/klogd then do

> sudo /etc/init.d/klogd stop
> sudo /etc/init.d/klogd start
> ps aux | grep logd
syslog 6645 0.0 0.1 1912 728 ? Ss 01:34 0:00 /sbin/syslogd -u syslog
root 6698 0.0 0.2 2496 1400 ? Ss 01:35 0:00 /sbin/klogd /proc/kmsg
jj 6959 0.0 0.1 2972 748 pts/0 R+ 01:48 0:00 grep logd

what you are looking for here is that dd isn't list, like above. Now you should be able to try and recreate the corrupted messages again. If the corrupt messages still happen, we can try dumping /proc/kmsg directly to a file bypassing klogd and syslog entirely.

edit /etc/init.d/klogd again, restore the klogd command by deleting the command and removing the commenting so it looks like

    # start klogd as non-root with reading from kmsgpipe
    start-stop-daemon --start --quiet --chuid klog --exec $binpath -- $KLOGD

now copy the dd command line and edit it so it looks like (the only part that is changed is of= at the end)
    # shovel /proc/kmsg to pipe readable by klogd user
# start-stop-daemon --start --pidfile $kmsgpidfile --exec /bin/dd -b -m -- bs=1 if=/proc/kmsg of=$kmsgpipe
    start-stop-daemon --start --pidfile $kmsgpidfile --exec /bin/dd -b -m -- bs=1 if=/proc/kmsg of=/tmp/kmsg-dump

save and then do

> sudo /etc/init.d/klogd stop
> sudo /etc/init.d/klogd start

you can then try recreating the corrupted messages again. genprof will work but it won't find any messages, to see if the messages are corrupt you can look at the /tmp/kmsg-dump file. If they are still corrupt the bug is in the kernel, and I will have to take a closer look at the audit / printk interface.

[Vajra Vrtti (vajravrtti)]

I coudn't find the AppArmor audit messages anywhere, after restarting klogd.
I'm attaching is the *complete* console of the test, with my comments prefixed with '###'.

[John Johansen (jjohansen)]

your console log (near the end) shows that klogd is not running, which means none of the kernel messages will get logged.

21:06:01~>ps aux | grep logd
syslog 5093 0.1 0.0 1916 700 ? Ss 20:35 0:03 /sbin/syslogd -u syslog
ubuntu 8032 0.0 0.0 2976 768 pts/0 R+ 21:06 0:00 grep logd

when I do this I get
jj@jj-desktop:~$ ps aux | grep logd
syslog 4117 0.0 0.1 1912 704 ? Ss 12:16 0:00 /sbin/syslogd -u syslog
root 5968 0.4 0.2 2496 1392 ? Ss 12:23 0:00 /sbin/klogd /proc/kmsg
jj 5992 0.0 0.1 2972 748 pts/0 R+ 12:23 0:00 grep logd

Can you try restarting your /etc/init.d/klogd again? Perhaps even reboot with the edited initscript and see if klogd starts.
If that doesn't work I would suggest reediting the file, the edit looks good but maybe it picked up a hidden character that isn't liked.

[Vajra Vrtti (vajravrtti)]

Just rebooting didn't help. I got the same response as before. I'll restore the original /etc/init.d/klogd and try the procedure again from the beginning.

[Vajra Vrtti (vajravrtti)]

I restored the original /etc/init.d/klogd and edited it again. I retyped all space characters in the new start command, to make sure there were no hidden characters. But klogd is still not running after the stop/start or reboot. Complete console attached.

[John Johansen (jjohansen)]

hmm, strange it works for me. Is there away that I can get a login on the machine, and take a look at what is going on?

If not I will see what else we can do.

[Vajra Vrtti (vajravrtti)]

The problem is not in klogd or syslog. I dumped /proc/kmsg directly to /tmp/kmsg-dump, as you said, and found several corrupted messages there (first in line 312, then several from line 1493 on). I'm attaching the complete file.

[Vajra Vrtti (vajravrtti)]

It may not be necessary anymore but I found out why I couldn't start klog. The problem was an AppArmor profile (sbin.klogd, part of the apparmor-profiles package) in enforce mode, which only allowed /sbin/klogd read access to /proc/kmsg. After disabling the profile I could start klogd:

18:36:25/etc/apparmor.d>sudo ln -s /etc/apparmor.d/sbin.klogd /etc/apparmor.d/disable/
18:37:21/etc/apparmor.d>sudo apparmor_parser -R /etc/apparmor.d/sbin.klogd
Removal succeeded for "/sbin/klogd".
18:38:01/etc/apparmor.d>sudo /etc/init.d/klogd stop
 * Stopping kernel log daemon... [ OK ]
18:45:23/etc/apparmor.d>sudo start-stop-daemon --start --verbose --exec /sbin/klogd -- /proc/kmsg
Starting /sbin/klogd...
18:46:31/etc/apparmor.d>ps aux | grep logd
syslog 4967 0.0 0.0 1916 732 ? Ss 18:29 0:00 /sbin/syslogd -u syslog
root 7063 0.4 0.1 2504 1396 ? Ss 18:46 0:00 /sbin/klogd /proc/kmsg
ubuntu 7065 0.0 0.0 2980 772 pts/0 R+ 18:46 0:00 grep logd
18:46:50/etc/apparmor.d>

[John Johansen (jjohansen)]

Okay thankyou, looking at the kmesg dump it would appear I need to look into the kernel auditing code more closely.

As for not being able to start klogd, sorry about that I seemed to have edited my local profiles for testing long ago and had forgotten about making the changes.

[Carlos Ramirez (carlosfabianramirez)]

We are closing this bug report because it lacks the information we need to investigate the problem, as described in the previous comments. Please reopen it if you can give us the missing information, and don't hesitate to submit bug reports in the future. To reopen the bug report you can click on the current status, under the Status column, and change the Status back to "New". Thanks again!

[Jacob Torrey (ranok)]

I also have this problem, where logprof spits out junk data on my Intrepid IBM T60.

[thosjo (thomas-sjogren)]

See https://bugs.launchpad.net/opensuse/+source/apparmor/+bug/271252

[Jamie Strandboge (jdstrand)]

I just noticed a corrupted message on up to date Hardy, which trips up aa-genprof:
Mar 11 08:32:36 myhost kernel: [1579298.005506] audit(1236778356.334:171932): type=1502 operation="file_mmap" requested_mask="::r" denied_mask="::r" name="/bin/echo" pid=25777 profile="null-complain-profile" namespace="default"
Mar 11 08:32:36 myhost kernel: [1579298.005529] audit(1236778356.334:171933): type=1502 operation="file_mmap" requested_mask="::mr" denied_mask="::mrme="/bin/echo" pid=25778 profile="null-complain-profile" namespace="default"
Mar 11 08:32:36 myhost kernel: [1579298.010021] audit(1236778356.344:171977): type=1502 operation="file_mmap" requested_mask="::mr" denied_mask="::mr" name="/bin/echo" pid=25778 profile="null-complain-profile" namespace="default"

Notice the 2nd messge, it has:
...denied_mask="::mrme="/bin/echo"...

I was investigating bug #340183 using the test case there. It may be some sort of race condition as I could not reproduce in a kvm Hardy guest VM, but can quite easily on my x86_64 server (with the -server kernel).

Marking Confirmed.

[Sergio Zanchetta (primes2h)]

The 18 month support period for Gutsy Gibbon 7.10 has reached its end of life -
http://www.ubuntu.com/news/ubuntu-7.10-eol . As a result, we are closing the
Gutsy task.

[Thomas Ohms (tohms)]

As stated in https://bugs.launchpad.net/opensuse/+source/apparmor/+bug/271252/comments/21 bug was fixed and released in intrepid-updates. Anyone can confirm it for intrepid? What about Jaunty? Still matters? Reporters please update bug with that information.

[Vajra Vrtti (vajravrtti)]

I will recreate the Firefox profile from scratch (which generates a lot o log messages) in both Intrepid and Jaunty and report the result.

[Vajra Vrtti (vajravrtti)]

Firefox Apparmor profiles successfully created in Intrepid and Jaunty, both systems with latest kernels and all updates applied. No corrupted audit messages found in /var/log/messages.

[Thomas Ohms (tohms)]

Ok, so fix for Intrepid and Jaunty works.
Question to upstreamers: Can we backport fix to Hardy, too?

[Rolf Leggewie (r0lf)]

Hardy has seen the end of its life and is no longer receiving any updates. Marking the Hardy task for this ticket as "Won't Fix".