aa-genprof creates empty profiles from /var/log/messages entries (works fine with auditd)

[Dariusz Suchojad]

Jaunty Beta Freeze Exception Request: please see comment https://bugs.launchpad.net/ubuntu/jaunty/+source/apparmor/+bug/340183/comments/23

Binary package hint: apparmor

Hello,

I'd say the bug report I'm opening is a duplicate of #294600, however Steve Beattie
said #294600 was a dup of #271252 which deals with a completely different case.
Not sure whether I should really open it as a new bug but here it is anyway.

aa-genprof generates an empty profile when it reads audit messages from
/var/log/messages. It works fine, i.e. produces a non-empty profile when auditd
is installed.

Take a look at apparmor_var_log_messages.txt attachment - here you can see that
aa-genprof asks no questions at all, it directly jumps to generating a new profile.

After installing auditd it's a completely different situation, here aa-genprof has noticed
there were some audit events generated and starts asking the questions.

The first lines of both attachments are the sample log entries, they're
different on the first two columns.

It's

type=1502 audit(1236632754.531:4542): in /var/log/messages

and

type=APPARMOR_ALLOWED msg=audit(1236632965.286:4973): in /var/log/audit/audit.log

I'm not sure why they're different but aa-genprof apparently chokes on the
former while having no problems with the latter.

It's auditd 1.7.4-1 and apparmor 1289-0ubuntu4.1 as reported by dpkg -l.

I'd like to investigate it further however I'm not sure what to take a look next?
Can you please guide me a bit here?

PS. By an empty profile I mean something like this

#include <tunables/global>

/home/dsuch/bin/ea.sh flags=(complain) {
  #include <abstractions/base>

}

[Jamie Strandboge (jdstrand)]

I can confirm that aa-genprof is not working right.

TEST CASE:
1. create $HOME/foobar.sh:
2. sudo aa-genprof.sh $HOME/foobar.sh
3. in another window, run $HOME/foobar.sh
4. in the aa-genprof window, do (S)can -- it does not prompt. Tried (S)can again, still no prompt.

Here are the logs:
Mar 11 07:32:59 myhost kernel: [50805.318822] type=1505 audit(1236774779.608:368): operation="profile_load" name="/home/jamie/foobar.sh" name2="default" pid=13649
Mar 11 07:33:07 myhost kernel: [50812.879558] type=1502 audit(1236774787.169:369): operation="inode_permission" requested_mask="::r" denied_mask="::r" fsuid=1000 name="/bin/dash" pid=13726 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.879589] type=1502 audit(1236774787.169:370): operation="file_mmap" requested_mask="::mr" denied_mask="::r" fsuid=1000 name="/bin/dash" pid=13726 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.879606] type=1502 audit(1236774787.169:371): operation="file_mmap" requested_mask="::r" denied_mask="::r" fsuid=1000 name="/bin/dash" pid=13726 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.880123] type=1502 audit(1236774787.172:372): operation="file_mprotect" requested_mask="::r" denied_mask="::r" fsuid=1000 name="/bin/dash" pid=13726 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.880417] type=1502 audit(1236774787.172:373): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=1000 name="/home/jamie/foobar.sh" pid=13726 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.880817] type=1502 audit(1236774787.172:374): operation="inode_permission" requested_mask="::x" denied_mask="::x" fsuid=1000 name="/bin/ls" pid=13727 profile="/home/jamie/foobar.sh"
Mar 11 07:33:07 myhost kernel: [50812.880842] type=1504 audit(1236774787.172:375): operation="exec" info="set profile" pid=13727 profile="null-complain-profile"
Mar 11 07:33:07 myhost kernel: [50812.880853] type=1502 audit(1236774787.172:376): operation="file_permission" requested_mask="::r" denied_mask="::r" fsuid=1000 name="/bin/ls" pid=13727 profile="null-complain-profile"
Mar 11 07:33:07 myhost kernel: [50812.880906] type=1502 audit(1236774787.172:377): operation="file_permission" requested_mask="::r" denied_mask="::r" fsuid=1000 name="/bin/ls" pid=13727 profile="null-complain-profile"
Mar 11 07:33:18 myhost kernel: [50824.044090] __ratelimit: 4179 callbacks suppressed
Mar 11 07:33:18 myhost kernel: [50824.044094] type=1505 audit(1236774798.332:1771): operation="profile_replace" name="/home/jamie/foobar.sh" name2="default" pid=13870

Here is the generated profile:
# Last Modified: Wed Mar 11 07:32:59 2009
#include <tunables/global>

/home/jamie/foobar.sh {
  #include <abstractions/base>

  /bin/dash ix,

}

[Jamie Strandboge (jdstrand)]

Oh, and I do not have auditd installed either.

[Jamie Strandboge (jdstrand)]

Milestoned for ubuntu-9.04-beta as this needs to be fixed before release. Adjust as necessary.

[Jamie Strandboge (jdstrand)]

I forgot to give the contents of foobar.sh:
#!/bin/sh

for i in `ls /`
do
    /bin/echo "$i"
done

This of course needs to be chmod 755.

[Jamie Strandboge (jdstrand)]

Also confirmed on Intrepid apparmor 2.3+1289-0ubuntu4 and 2.3+1289-0ubuntu4.1.

[Jamie Strandboge (jdstrand)]

Updated test script:
#!/bin/sh

tmp="$HOME/foobar.tmp"
trap "rm -rf $tmp" EXIT HUP INT QUIT TERM
touch "$tmp"

for i in `ls /`
do
    /bin/echo "$i"
done

[Jamie Strandboge (jdstrand)]

Doing the same test on Hardy i386 virtual machine and on real i386 hardware resulted in:
$ sudo aa-genprof $HOME/foobar.sh
Writing updated profile for /home/jamie/foobar.sh.
Setting /home/jamie/foobar.sh to complain mode.

Please start the application to be profiled in
another window and exercise its functionality now.

Once completed, select the "Scan" button below in
order to scan the system logs for AppArmor events.

For each AppArmor event, you will be given the
opportunity to choose whether the access should be
allowed or denied.

Profiling: /home/jamie/foobar.sh

[(S)can system log for SubDomain events] / (F)inish
Reading log entries from /var/log/messages.
Updating AppArmor profiles in /etc/apparmor.d.

Log contains unknown mode 1236777289.604:351):.

Hardy i386 kern.log entries are attached. This is a

[Jamie Strandboge (jdstrand)]

Sorry for the noise on Hardy. Marking Hardy task as Invalid because I didn't properly remove the profile while testing and I can't reproduce anymore. It would be a different bug anyway, so I'll file a new one if I can reproduce.

[Jamie Strandboge (jdstrand)]

The Hardy issue seems to be bug #160238.

[Steve Beattie (sbeattie)]

I've committed a tentative fix upstream that I believe addresses the issue, in https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1389 . Attached is the patch as applied to the tip of the ubuntu apparmor bzr tree and I've built packages in my ppa for testing in jaunty that include this patch at https://launchpad.net/~sbeattie/+archive/ppa ; only the updated libapparmor1 package should be needed. Testing and feedback welcome.

https://help.launchpad.net/Packaging/PPA#Adding%20a%20PPA%20to%20your%20Ubuntu%20repositories describes how to install packages from a PPA.

Thanks.

[Dariusz Suchojad (dsuch)]

Hello Steve,

is there any chance you could build the package for Intrepid too? I'd like to
give it a go and see if it helps with the original issue.

Thanks.

[Steve Beattie (sbeattie)]

@dsuch: yes, I've submitted apparmor - 2.3+1289-0ubuntu4.2~ppa1 for building on intrepid in my ppa (again, at https://launchpad.net/~sbeattie/+archive/ppa). However, I understand there's a bit of a backlog on the ppa build hosts, so it may not be available for a little while.

Thanks for offering to test!

[Dariusz Suchojad (dsuch)]

Unfortunately, it still doesn't work with 2.3+1289-0ubuntu4.2~ppa1, even if I
explicitly tell aa-genprof to read the events from /var/log/messages (-f switch).

Is there any way to run it in a I_MEAN_REALLY_VERBOSE_DEBUG_MODE perhaps? :-)

I have completely removed each of the packages before testing the configurations
below, including manually rm -rf /etc/apparmor*

        apparmor | auditd | OK? |
---------------------------------------------------------------------------
2.3+1289-0ubuntu4.11.7.4-1 | n/a | no |
2.3+1289-0ubuntu4.11.7.4-1 | 1.7.4-1 | yes |
2.3+1289-0ubuntu4.2~ppa1 | n/a | no |
2.3+1289-0ubuntu4.2~ppa1 | 1.7.4-1 | yes |
2.3+1289-0ubuntu4.2~ppa1 (-f /var/log/messages) | n/a | no |

What I don't understand is why aa-genprof doesn't mark the logs with a beginning
marker to know where to start reading messages from? I.e. the first line in logs
after starting aa-genprof is

Mar 14 14:19:03 xerxes kernel: [ 2827.572460] type=1505 audit(1237036743.070:36316): operation="profile_load" name="/home/dsuch/bin/ea.sh" name2="default" pid=11641

Shouldn't there always be a GenProf marker first?

[Steve Beattie (sbeattie)]

On Sat, Mar 14, 2009 at 01:37:02PM -0000, Dariusz Suchojad wrote:
> apparmor | auditd | OK? |
> ---------------------------------------------------------------------------
> 2.3+1289-0ubuntu4.11.7.4-1 | n/a | no |
> 2.3+1289-0ubuntu4.11.7.4-1 | 1.7.4-1 | yes |

Can you tell me where the above apparmor version came
from? I don't see it on the list of published packages at
https://launchpad.net/ubuntu/+source/apparmor .

> 2.3+1289-0ubuntu4.2~ppa1 | n/a | no |
> 2.3+1289-0ubuntu4.2~ppa1 | 1.7.4-1 | yes |
> 2.3+1289-0ubuntu4.2~ppa1 (-f /var/log/messages) | n/a | no |

Can you make sure you're updating libapparmor1 at the same time? As
that's where I believe the issue is located. IIRC, the packaging is set
up so that there is not a tight version dependency between the various
packages, and so upgrading the apparmor package won't pull in the
libapparmor1 update by default.

('dpkg -l "*apparmor*" auditd libaudit0' will report versions for all
the apparmor and audit packages installed.)

> What I don't understand is why aa-genprof doesn't mark the logs with a beginning
> marker to know where to start reading messages from? I.e. the first line in logs
> after starting aa-genprof is
>
> Mar 14 14:19:03 xerxes kernel: [ 2827.572460] type=1505
> audit(1237036743.070:36316): operation="profile_load"
> name="/home/dsuch/bin/ea.sh" name2="default" pid=11641
>
> Shouldn't there always be a GenProf marker first?

You should see something like

  Mar 14 11:13:56 jj-amd64 ubuntu: GenProf: 4995bc33fda53c4f5f9b324c2ccff407

in /var/log/messages, at least when auditd is not running.

Ah, I see one additional problem, if /var/log/audit/audit.log exists,
even if auditd is not running, genprof won't write the marker. Hrm.

--
Steve Beattie
<email address hidden>
http://NxNW.org/~steve/

[Steve Beattie (sbeattie)]

[Hrm, my reply be email didn't come through; apologies if this comment gets sent twice.]

On Sat, Mar 14, 2009 at 01:37:02PM -0000, Dariusz Suchojad wrote:
> apparmor | auditd | OK? |
> ---------------------------------------------------------------------------
> 2.3+1289-0ubuntu4.11.7.4-1 | n/a | no |
> 2.3+1289-0ubuntu4.11.7.4-1 | 1.7.4-1 | yes |

Can you tell me where the above apparmor version came
from? I don't see it on the list of published packages at
https://launchpad.net/ubuntu/+source/apparmor .

> 2.3+1289-0ubuntu4.2~ppa1 | n/a | no |
> 2.3+1289-0ubuntu4.2~ppa1 | 1.7.4-1 | yes |
> 2.3+1289-0ubuntu4.2~ppa1 (-f /var/log/messages) | n/a | no |

Can you make sure you're updating libapparmor1 at the same time? As
that's where I believe the issue is located. IIRC, the packaging is set
up so that there is not a tight version dependency between the various
packages, and so upgrading the apparmor package won't pull in the
libapparmor1 update by default.

('dpkg -l "*apparmor*" auditd libaudit0' will report versions for all
the apparmor and audit packages installed.)

> What I don't understand is why aa-genprof doesn't mark the logs with a beginning
> marker to know where to start reading messages from? I.e. the first line in logs
> after starting aa-genprof is
>
> Mar 14 14:19:03 xerxes kernel: [ 2827.572460] type=1505
> audit(1237036743.070:36316): operation="profile_load"
> name="/home/dsuch/bin/ea.sh" name2="default" pid=11641
>
> Shouldn't there always be a GenProf marker first?

You should see something like

  Mar 14 11:13:56 jj-amd64 ubuntu: GenProf: 4995bc33fda53c4f5f9b324c2ccff407

in /var/log/messages, at least when auditd is not running.

Ah, I see one additional problem, if /var/log/audit/audit.log exists,
even if auditd is not running, genprof won't write the marker. And
of course, /var/log/audit/audit.log is not removed when the auditd
package is uninstalled. Hrm.

[Dariusz Suchojad (dsuch)]

>> 2.3+1289-0ubuntu4.11.7.4-1 | 1.7.4-1 | yes |
> Can you tell me where the above apparmor version came
> from? I don't see it on the list of published packages at
> https://launchpad.net/ubuntu/+source/apparmor .

Err.. it's my fault, should've been 2.3+1289-0ubuntu4.1, 1.7.4-1 came from the
auditd version.

> Can you make sure you're updating libapparmor1 at the same time?

Here's the dpkg -l output

dsuch@xerxes:~$ dpkg -l "*apparmor*" auditd libaudit0
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Cfg-files/Unpacked/Failed-cfg/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Hold/Reinst-required/X=both-problems (Status,Err: uppercase=bad)
||/ Name Version Description
+++-=================================-=================================-==================================================================================
ii apparmor 2.3+1289-0ubuntu4.2~ppa1 User-space parser utility for AppArmor
un apparmor-docs <none> (no description available)
un apparmor-parser <none> (no description available)
un apparmor-profiles <none> (no description available)
ii apparmor-utils 2.3+1289-0ubuntu4.2~ppa1 Utilities for controlling AppArmor
rc auditd 1.7.4-1 User space tools for security auditing
ii libapparmor-perl 2.3+1289-0ubuntu4.2~ppa1 AppArmor library Perl bindings
ii libapparmor1 2.3+1289-0ubuntu4.2~ppa1 changehat AppArmor library
rc libaudit0 1.7.4-1 Dynamic library for security auditing
dsuch@xerxes:~$

> You should see something like
> Mar 14 11:13:56 jj-amd64 ubuntu: GenProf:
> 4995bc33fda53c4f5f9b324c2ccff407
> in /var/log/messages, at least when auditd is not running.

Yes, I can see it now. See the attached 2.3+1289-0ubuntu4.2~ppa1_var_log_messages.txt file
with events from /var/log/messages.

> Ah, I see one additional problem, if /var/log/audit/audit.log exists,
> even if auditd is not running, genprof won't write the marker. And
> of course, /var/log/audit/audit.log is not removed when the auditd
> package is uninstalled. Hrm.

The precedence is defined in /etc/apparmor/logprof.conf, right?

Anyway, after removing the /var/log/audit/audit.log it still doesn't work,
sorry to say it but seems like nothing has changed.

Can you attach a sample of /var/log/messages where it does work? Perhaps there's still something different elsewhere?

[Launchpad Janitor (janitor)]

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

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

  [ Kees Cook ]
  * abstractions/base: allow /proc/$pid/maps (LP: #343287).
  * abstractions/*: clean up lib, lib32, lib64 semantics (LP: #342200).
  * abstractions/nameservice: fix up paths for nscd (LP: #342198).
  * parser/rc.apparmor.functions, debian/apparmor.init: LSB-ify startup
    messages (LP: #295200).

  [ Steve Beattie ]
  * libapparmor/src/scanner.l: adjust lexer to fix matching updated audit
    messages (LP: #340183) from upstream commit
    https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1389
  * debian/source_apparmor.py: add a per-package apport hook (LP: #342554).

 -- Kees Cook <email address hidden> Wed, 18 Mar 2009 21:18:01 -0700

[Dariusz Suchojad (dsuch)]

> This bug was fixed in the package apparmor - 2.3+1289-0ubuntu9
> ---------------
> apparmor (2.3+1289-0ubuntu9) jaunty; urgency=low

Are you sure it's really been fixed for Jaunty? I'm not using it yet
but I can still confirm I'm still having the same problems in Intrepid.

[Steve Beattie (sbeattie)]

That's correct, the upload by Kees only fixes part of the issue. Can you please try apparmor 2.3+1289-0ubuntu10~ppa1 (jaunty) or apparmor 2.3+1289-0ubuntu4.2~ppa2 (intrepid) when they appear in my ppa at https://launchpad.net/~sbeattie/+archive/ppa/ . I think I've got the rest of the fix in place, but wouldlike confirmation before another upload to jaunty occurs (but I would like to get this in before the beta freeze, if it does address the issue).

Also, there is a debugging mode you can enable, run with the environment variable LOGPROF_DEBUG set, which will write a debug log to /var/log/apparmor/logprof_debug_<pid>.log (versions prior to these uploads would write to /tmp/logprof_debug_<pid>.log -- gack!).

Thanks for your patience, and your feedback is appreciated!

[Dariusz Suchojad (dsuch)]

After a vivid #ubuntu-hardened IRC session (thanks again sbeattie and jjohansen), I can no longer reproduce
the problems I have originally reported when using 2.3+1289-0ubuntu4.2~ppa4.

[Steve Beattie (sbeattie)]

Please consider this for a Jaunty Beta freeze exception.

Attached is a debdiff to fix this issue; it also cherrypicks a couple of issues fixed upstream that came to light in testing this fix, namely a situation where the tools could generate an invalid apparmor profile, and where the tools would, in repeated invocations, ask about the same networking events, even though the profile in question had already been modified to allow them.

All the changes in question are limited to the apparmor-utils perl module Immunix/SubDomain.pm; and as the tools do not correctly parse the generated log messages and thus are non-functional, the risk of regression from this fix is low, and should have no impact on the rest of the distribution.

I have tested these changes in packages built for jaunty in my ppa, and as Dariusz Suchojad mentioned, he tested the same changes as applied to intrepid packages, also built from my ppa.

Thanks.

[Martin Pitt (pitti)]

Sponsored, and got Steve's ACK for beta.

[Launchpad Janitor (janitor)]

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

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

  * utils/SubDomain.pm:
    - teach utils about rearranged syslog audit messages (LP: #340183)
      from upstream commit
      https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1393
    - fix corruption of profiles, from upstream commit
      https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1354
    - don't ask about networking events over and over again, from upstream commit
      https://forgesvn1.novell.com/viewsvn/apparmor?view=rev&revision=1296
    - use apparmor logdir instead of /tmp to write debugging log

 -- Steve Beattie <email address hidden> Thu, 19 Mar 2009 03:05:07 -0700

[Steve Beattie (sbeattie)]

Assigning the task of putting together an Intrepid SRU to myself.