aa-logprof generates faulty output messages

Can confirm this problem. I can't run aa-logprof from Intreprid beta

jory01@jory01-ubuntu:~$ sudo aa-logprof
[sudo] password for jory01:
Reading log entries from /var/log/messages.
Updating AppArmor profiles in /etc/apparmor.d.
sys--KeKeInspectingSyesysBBBBBipesysInspectingCInitiInitiBIOS-pBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eDACPIACPIACPIACPIACPIACPIboot#########ZDNoHigheACPISPPAPEBuiKeEnEnInitiPIDhTSCTSCDetectedCcDentInode-cvifpvChecSCSecuSEAppAInitiInitiInitiCPUCPUChecSFACPIACPIACPISSBTotnet_BootingpTiNETEISAbusACPIPCIPCIACPIACPIACPIACPIpcipciHPETnotenpcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIACPIACPIACPIACPIACPIpnpACPIpnppnppnppnppnppnpACPIPnPBIOSPCINETNETNetNetNetNettAppAsystesystesystesystesystesystesystesystesystesystesystesystesystesystepcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIpcipcibusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusNETIPTCPestTCPbindhTCPTCPNETchecFHugeTVFSDquot-cioscheduioscheduioscheduioscheduisisSeseACPIsesebinputPNPseseEISAEISAcpuidcpuidTCPcubicUsingIPINo-ShottyttycBIOSEDDfEDDFinputfuseinitACPIpACPItheACPIACPIusbcousbcousbcoACPIehci_hcdehci_hcdehci_hcdehci_hcdehci_hcdUSBUniveehci_hcdusbusbhubhubSCSIsubsysteACPIuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubACPIuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubusbtgtgethethethohciohcibssbpppscsiscsiusbscsiscsiscsiscsiDsdsdsdsdsdsdsdsdsdsUnifoPEudevdvepci_hotpshpchpiTCO_vendoiTCO_iTCO_iTCO_inteACPIACPIACPIinputACPIinputACPIinputACPInvidiYentYentYentYentYentSocYentpccspcpcYentYentSocYentpccspcpcppinputACPIBNETBBBusbconvidiNVIntebinputBinteinteinputinputdcdbcscscscscscscscscscsAddingEip_tACPIppdevCBBBBBBBBBBnvidiinputfifififibbbNETtgtgpupupuNETADD----------------------__convidibPFFPPSuspendingcsdpsebNVInteehci_hcduhci_hcduhci_hcduhci_hcdACPIDisPPACPIuhci_hcduhci_hcduhci_hcdehci_hcdIntesdsdsdNVohcibsepsdADDinputbbbADDtgtgADDsysInspectingCInitiInitiBIOS-pBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eDACPIACPIACPIACPIACPIACPIboot#########ZDNoHigheACPISPPAPEBuiKeEnEnInitiPIDhTSCTSCDetectedCcDentInode-cvifpvChecSCSecuSEAppAInitiInitiInitiCPUCPUChecSFACPIACPIACPISSBTotnet_BootingpTiNETEISAbusACPIPCIPCIACPIACPIACPIACPIpcipciHPETnotenpcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIACPIACPIACPIACPIACPIpnpACPIpnppnppnppnppnppnpACPIPnPBIOSPCINETNETNetNetNetNettAppAsystesystesystesystesystesystesystesystesystesystesystesystesystesystepcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIpcipcibusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusNETIPTCPestTCPbindhTCPTCPNETchecFHugeTVFSDquot-cioscheduioscheduioscheduioscheduisisSeseACPIsesebinputPNPseseEISAEISAcpuidcpuidTCPcubicUsingIPINo-ShoBIOSEDDfEDDFinputfuseinitACPIpACPItheACPIACPIusbcousbcousbcoUSBUniveACPIuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubSCSIsubsysteuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubACPIuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhubhubusbACPIehci_hcdehci_hcdehci_hcdehci_hcdehci_hcdehci_hcdusbusbhubhubtgtgethethethohciohcibssbpppscsiscsiscsiscsiscsiscsiDsdsdsdsdsdsdsdsdsdsUnifousbPEEusbEEudevdveiTCO_vendopci_hotpiTCO_iTCO_iTCO_shpchpinputinteACPIACPIACPIinputACPIinputACPIinputACPIinputinputppinputACPInvidiYentYentYentYentYentSocYentpccspc...

That's awful. Can you please attach /var/log/messages to help us
diagnose the problem. Thanks!

The latest audit messages are actually not present in /var/log/messages or /var/log/daemon.
They do however show up when running dmesg.

root@thosjo-lab:~# grep audit /var/log/messages /var/log/daemon.log| wc -l
0
root@thosjo-lab:~# dmesg|grep audit| wc -l
646

root@thosjo-lab:~# dmesg|grep audit | tail -n5
[28191.924373] type=1502 audit(1225212747.947:22163): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=0 name="/proc/loadavg" pid=4836 profile="/usr/lib/sm.bin/sendmail"
[28196.924211] type=1502 audit(1225212752.947:22164): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=0 name="/proc/loadavg" pid=4836 profile="/usr/lib/sm.bin/sendmail"
[28196.924383] type=1502 audit(1225212752.947:22165): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=0 name="/proc/loadavg" pid=4836 profile="/usr/lib/sm.bin/sendmail"
[28201.924204] type=1502 audit(1225212757.947:22166): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=0 name="/proc/loadavg" pid=4836 profile="/usr/lib/sm.bin/sendmail"
[28201.924391] type=1502 audit(1225212757.947:22167): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=0 name="/proc/loadavg" pid=4836 profile="/usr/lib/sm.bin/sendmail"

root@thosjo-lab:~# aa-logprof
Reading log entries from /var/log/messages.
Updating AppArmor profiles in /etc/apparmor.d.
sys------------------besyspupupu----------------besyspupupu--sys--------------------------------------------root@thosjo-lab:~#

root@thosjo-lab:~# zgrep audit /var/log/* | tail -n 5
/var/log/messages.3.gz:Oct 1 16:42:33 thosjo-lab kernel: [23249.323475] type=1502 audit(1222872153.928:30857): operation="socket_recvmsg" family="inet" sock_type="stream" protocol=6 pid=7184 profile="null-complain-profile"
/var/log/messages.3.gz:Oct 1 16:42:34 thosjo-lab kernel: [23249.323739] type=1502 audit(1222872153.928:30858): operation="socket_recvmsg" family="inet" sock_type="stream" protocol=6 pid=7184 profile="null-complain-profile"
/var/log/messages.3.gz:Oct 1 16:42:34 thosjo-lab kernel: [23249.323778] type=1502 audit(1222872153.928:30859): operation="socket_recvmsg" family="inet" sock_type="stream" protocol=6 pid=7184 profile="null-complain-profile"
/var/log/messages.3.gz:Oct 1 16:42:34 thosjo-lab kernel: [23249.324893] type=1502 audit(1222872153.930:30860): operation="file_lock" requested_mask="k::" denied_mask="k::" fsuid=1000 name="/home/thosjo/.mozilla/firefox/y5e0krtz.default/urlclassifier3.sqlite" pid=7197 profile="null-complain-profile"
/var/log/messages.3.gz:Oct 1 16:42:40 thosjo-lab kernel: [23254.518714] type=1502 audit(1222872159.122:30896): operation="socket_recvmsg" family="inet" sock_type="stream" protocol=6 pid=7184 profile="null-complain-profile"

root@thosjo-lab:~# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 8.10
Release: 8.10
Codename: intrepid

root@thosjo-lab:~# uname -a && dpkg -l |grep apparmor
Linux thosjo-lab 2.6.27-7-generic #1 SMP Fri Oct 24 06:42:44 UTC 2008 i686 GNU/Linux

ii apparmor 2.3+1289-0ubuntu4 User-space parser utility for AppArmor
ii...

I run aa-logprof today and got the same error. I will also provide /var/log/messages as an attachment
jory01@jory01-ubuntu:~$ sudo aa-logprof
Reading log entries from /var/log/messages.
Updating AppArmor profiles in /etc/apparmor.d.
sys______tgtgtgtgtgtg____________________________nvidi____ip__esysInspectingCInitiInitiBIOS-pBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eBIOS-eDACPIACPIACPIACPIACPIACPIboot#########ZDNoHigheACPISPPAPEBuiKeEnEnInitiPIDhTSCTSCDetectedCcDentInode-cvifpvChecSCSecuSEAppAInitiInitiInitiCPUCPUChecSFACPIACPIACPISSBTotnet_BootingpTiNETEISAbusACPIPCIPCIACPIACPIACPIACPIpcipciHPETnotenpcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIACPIACPIACPIACPIACPIpnpACPIpnppnppnppnppnppnpACPIPnPBIOSPCINETNETNetNetNetNettAppAsystesystesystesystesystesystesystesystesystesystesystesystesystesystepcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipcipciACPIpcipcibusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusbusNETIPTCPestTCPbindhTCPTCPNETchecFHugeTVFSDquot-cioscheduioscheduioscheduioscheduisisSeseACPIsesebinputPNPseseEISAEISAcpuidcpuidTCPcubicUsingIPINo-ShoBIOSEDDfEDDFinputfuseinitACPIpACPItheACPIACPIusbcousbcousbcoACPIehci_hcdehci_hcdehci_hcdehci_hcdehci_hcdUSBUniveehci_hcdusbusbhubhubSCSIsubsysteACPIuhci_hcduhci_hcduhci_hcduhci_hcdusbusbhu
Create New User?

(Y)es / [(N)o]

I see similar problems on Intrepid. aa-logprof outputs lots of garbage (and also seems to miss some real apparmor messages).
IMHO fixing this bug should have higher priority, apparmor is a security-related program and used to work fine in Hardy.

I can also confirm this problem and I'm setting status to confirmed. I've had to disable many of my custom profiles due to changes in Ubuntu 8.10 and the increased difficulty in debugging and correcting the problems.

I believe the root cause of this problem is that the lex grammar in libapparmor used for parsing log messages is not robust enough.

I spent a bit of time instrumenting logprof and found that the garbage characters are printed in the middle of when it calls LibAppArmor::parse_record. This function in libapparmor uses yacc and lex to parse log messages, but when the lex scanner encounters characters that don't match the grammar that has been specified, the default is to print those characters. I think that's what's happening here.

It looks like the format for audit messages that show up in /var/log/messages when auditd is not running changed between Hardy and Intrepid.

The type=NNNN part of the message was after the "audit(NNNNNNNNNN.NNN:NN):" part in Hardy, but before it in Intrepid and that's likely causing the log parsing code to break.

As a temporary workaround, I think installing the auditd package so that audit logs go to /var/log/audit/audit.log instead of /var/log/messages might work, but I'd suggest increasing max_log_file in /etc/audit/auditd.conf if AA is being used.

I think this patch might fix the problem. The format of audit messages that are redirected to syslog because auditd isn't running changed between Hardy and Intrepid and now have the type=NNNN field before the audit tag like--

Nov 1 22:24:43 box kernel: [ 158.113592] type=1503 audit(1225603483.635:5): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/7034/net/" pid=7034 profile="/usr/sbin/cupsd"

I believe this patch will address the moved type=NNNN field as well as capturing non-matching logfile input instead of printing it to stdout.

Applied patch.
I had to add /var/log/kernel to logprof.conf, otherwise it seems to work ok when it comes to parsing the messages.

# aa-logprof -f /var/log/kernel.0
Reading log entries from /var/log/kernel.0.
Updating AppArmor profiles in /etc/apparmor.d.
Complain-mode changes:

Profile: /usr/lib/sm.bin/sendmail
Network Family: inet
Socket Type: dgram

[(A)llow] / (D)eny / Audi(t) / Abo(r)t / (F)inish
Adding network access inet dgram to profile.

Profile: /usr/lib/sm.bin/sendmail
Network Family: inet
Socket Type: stream
[. snip . ]

# grep -A3 Changes apparmor_2.3+1289-0ubuntu5_i386.changes
Changes:
 apparmor (2.3+1289-0ubuntu5) intrepid; urgency=high
 .
   * applied patch by Jesse Michael, launchpad #271252

# dpkg -l |grep apparmor
ii apparmor 2.3+1289-0ubuntu5 User-space parser utility for AppArmor
ii apparmor-docs 2.3+1289-0ubuntu5 Documentation for AppArmor
ii apparmor-profiles 2.3+1289-0ubuntu5 Profiles for AppArmor Security policies
ii apparmor-utils 2.3+1289-0ubuntu5 Utilities for controlling AppArmor
ii libapache2-mod-apparmor 2.3+1289-0ubuntu5 changehat AppArmor library as an Apache modu
ii libapparmor-dev 2.3+1289-0ubuntu5 AppArmor development libraries and header fi
ii libapparmor-perl 2.3+1289-0ubuntu5 AppArmor library Perl bindings
ii libapparmor1 2.3+1289-0ubuntu5 changehat AppArmor library
ii libpam-apparmor 2.3+1289-0ubuntu5 changehat AppArmor library as a PAM module

Jesse: I think they're two distinct issues, but both should be fixed.
WRT the passthrough issue, I think just dropping not understood characters
is okay; it already tries to do that, though in other situations it moves
to the 'unknown_message' state and tries to save the rest of the message
in the ->info field. The log parsing library was originally targeted
towards parsing the output of auditd and not syslog (since the latter
is spoofable), and so has had less thought with respect to its design.

Dealing with the new format should definitely be fixed; you should
probably add the case where there's no dmesg timestamp (unless that option
is no longer configurable in the kernel) but the key_type is present;
this is less important for Ubuntu.

I've added testcases for both issues in the upstream svn repo, commits
1307 and 1308.

Novell bugzilla #304491 is about the original addition of support for parsing syslog messages (opensuse includes auditd by default, so supporting syslogd was a lower priority initially); newly filed Novell bugzilla #441381 is the correct one to reference here.

Attached is the patch that we'll likely go with upstream. Thanks.

SRU Request to fix bug 271252 and bug 292580

Impact: aa-logprof is completely unusable on intrepid, due to changes with kernel 2.6.27. Also, users of resolvconf will have problems with applications that are protected by apparmor and doing name service lookups.

See https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1310 for explanation of how the bug 271252 was addressed. Basically, the parser is adjusted for the type field move, and non-matching profile output is no longer sent to stdout. To fix bug 292580, this path was added to abstractions/nameservice:
/etc/resolvconf/run/resolv.conf r,

Attached is a debdiff fixing this bug and bug #292580. The debdiff also adds test cases for the testsuite.

TEST CASE
$ sudo aa-logprof (assuming there are audit messages in /var/log/kern.log)

This will fail as in the reporter's description. Patch fixes the problem, and restores aa-logprof functionality.

The regression potential for the fix for bug #292580 is negligible, as the nameservice abstraction is made more permissive. The regression potential is considered low for #271252, because aa-logprof is totally unusable right now. Running the testsuite showed no regressions with this patch.

Steve, as the person who signed off on the upstream patch, can you comment on the regression potential?

This bug was fixed in the package apparmor - 2.3+1289-0ubuntu5

---------------
apparmor (2.3+1289-0ubuntu5) jaunty; urgency=low

  * abstractions/nameservice: allow read access to
    /etc/resolvconf/run/resolv.conf (LP: #286080)
  * adjust src/grammar.y and src/scanner.l to account for the moved type=NNNN
    field in 2.6.27 kernels and capture non-matching logfile input instead of
    printing it to stdout (LP: #271252). Patch thanks to Jesse Michael and
    Steve Beattie.
    - https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1310
  * add syslog test cases to testsuite. Patch thanks to Steve Beattie.
    - https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1307
    - https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1308
    - https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1309

 -- Jamie Strandboge <email address hidden> Tue, 21 Oct 2008 09:09:58 -0500

Jamie, this package seems to indeed be accepted into jaunty, so surely 'fix released' is the correct state for that task?

Accepted into intrepid-proposed, please test and give feedback here. Please see https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Test case for aa-logprof works properly after the update. /etc/resolvconf/run/resolv.conf issue is also resolved.

TEST CASE for resolvconf:
$ sudo apt-get install resolvconf clamav-daemon
$ sudo /etc/init.d/clamav-daemon stop
$ sudo /etc/init.d/clamav-daemon start
$ tail /var/log/kern.log

Without the patch, kern.log will show on clamd startup:
Nov 5 13:26:32 sec-intrepid-i386 kernel: [82343.462840] type=1503 audit(1225913192.088:50): operation="inode_permission" requested_mask="::r" denied_mask="::r" fsuid=116 name="/etc/resolvconf/run/resolv.conf" pid=14446 profile="/usr/sbin/clamd"

Regression possibilities: given that in the default configuration (audit messages going to syslog rather than auditd), none of the messages are parsed properly by the library and thus are not being handed off to the tools, rendering them useless for updating profiles; it would be hard to regress from that. However, the changes do touch the core lexer and grammar of the parsing library, so it's possible that this fix could cause regressions for situations that currently work (namely, configurations where auditd is enabled). I'll test that configuration later today (assuming the packages got built finally).

The change is in a library that is entirely separate from the tool that loads apparmor policy into the kernel for enforcement (or the kernel enforcement code itself) and as such should not be able to cause any regressions around apparmor's ability to enforce policy; the library is only used for tools that need to handle apparmor events, like aa-logprof, which assists users in modifying policy based on rejections that occur.

Thanks.

I'm sorry, the clamav-daemon test case is invalid as the version in intrepid does not contain the nameservice line in /etc/apparmor.d/usr.sbin/clamd (I had a modified clamd profile installed that included the line). clamav-freshclam does have the nameservice line however. Here is the correct test case:

TEST CASE for resolvconf:
$ sudo apt-get purge clamav-freshclam
$ sudo apt-get install resolvconf
$ sudo apt-get install clamav-freshclam
$ tail /var/log/kern.log

Copied to intrepid-updates.