serialize_profile_from_old_profile() crash if file contains multiple profiles

The debug log indicates that this happens for profile '/sbin/dhclient', hat '/usr/lib/NetworkManager/nm-dhcp-client.action' - but unfortunately it's a "delayed" error which makes the debug log less useful :-(

Can you reproduce that crash? If yes, please attach your /var/log/audit/audit.log (or whatever logfile aa-logprof reads, see the message at startup) and the content of /etc/apparmor.d/ as tarball. (If you don't want to have everything in the public bugtracker, you can mail it to me - apparmor [at] cboltz.de)

Email sended

Thanks, I was able to reproduce the crash with your profiles and a hand-tuned log line even with the latest bzr trunk:

# python3 aa-logprof -d lp1528139/apparmor.d/ -f <(echo '[ 2590.544373] audit: type=1400 audit(1450688542.244:3848): apparmor="ALLOWED" operation="open" profile="/usr/lib/NetworkManager/nm-dhcp-client.action" name="/crash/me" pid=7983 comm="foo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0')
-> (A)llow
-> (V)iew Changes
-> enjoy the crash

The problem is that the /usr/lib/NetworkManager/nm-dhcp-client.action profile is stored in apparmor.d/sbin.dhclient (which contains multiple profiles). If I move it to a separate file, aa-logprof doesn't crash.

Now I "just" need to find out what is wrong - but that's easier with a reproducer available :-)
(Maybe the perfect answer is a total rewrite of serialize_profile_from_old_profile() which has more than one known bug, but that isn't something that will happen soon.)

To make things easier to debug, here's the minimal reproducer:

rm -ri lp1528139
mkdir lp1528139
echo '
/foo {
}
/bar {
  network inet6 dgram, # any rule handled by a *Rule class will cause the crash
}
' > lp1528139/lplp1528139.profile

python3 aa-logprof -d lp1528139/ -f <(echo '[ 2590.544373] audit: type=1400 audit(1450688542.244:3848): apparmor="ALLOWED" operation="open" profile="/foo" name="/crash/me" pid=7983 comm="foo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0')

So I have good and bad news.

Let me start with the bad news:

profile_data / write_prof_data (in serialize_profile_from_old_profile()) contain only one profile with its hats. This will explode if a file contains multiple profiles, as reported in this bug.

Fixing this needs lots of write_prof_data[hat] -> write_prof_data[profile][hat] changes (and of course also a change in the calling code) or, better option, a full rewrite of serialize_profile_from_old_profile().

Unfortunately I don't have the time to do the rewrite at the moment (I have other things on my TODO list), and doing the write_prof_data[hat] -> write_prof_data[profile][hat] is something that might introduce more breakage, so I'm not too keen to do that.

The good news - at least I have a way to avoid the crash ;-)

I'll wrap the serialize_profile_from_old_profile() in try/except. If it fails, the diff will include an error message and recommend to use 'View Changes b/w (C)lean profiles' instead, which is known to work even with the testcase in this bug.

=== modified file ./utils/apparmor/aa.py
--- utils/apparmor/aa.py 2015-12-21 00:13:57.215799543 +0100
+++ utils/apparmor/aa.py 2015-12-21 23:55:01.858211661 +0100
@@ -2368,7 +2368,12 @@
                         oldprofile = aa[which][which]['filename']
                     else:
                         oldprofile = get_profile_filename(which)
- newprofile = serialize_profile_from_old_profile(aa[which], which, '')
+
+ try:
+ newprofile = serialize_profile_from_old_profile(aa[which], which, '')
+ except AttributeError:
+ # see https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1528139
+ newprofile = "###\n###\n### Internal error while generating diff, please use '%s' instead\n###\n###\n" % _('View Changes b/w (C)lean profiles')

                     display_changes_with_comments(oldprofile, newprofile)

Sorry that this isn't a perfect solution, but I'm not too keen to spent lots of time on a function that needs to be rewritten anyway.

For the records: this bug causes a crash in 2.10 and bzr trunk. 2.9.x "only" displays a wrong diff.

Nice, launchpad killed the whitespace in the patch. See
https://lists.ubuntu.com/archives/apparmor/2015-December/009025.html
for a usable version ;-)

I patched aa.py file with standard Ubuntu version (2.10) but error still occurs.

sudo aa-logprof -f /var/log/kern.log
Reading log entries from /var/log/kern.log.
Updating AppArmor profiles in /etc/apparmor.d.
Traceback (most recent call last):
  File "/usr/sbin/aa-logprof", line 50, in <module>
    apparmor.do_logprof_pass(logmark)
  File "/usr/lib/python3/dist-packages/apparmor/aa.py", line 2176, in do_logprof_pass
    log = log_reader.read_log(logmark)
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 358, in read_log
    self.add_event_to_tree(event)
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 263, in add_event_to_tree
    rmask = rmask.replace('c', 'a')
AttributeError: 'NoneType' object has no attribute 'replace'

An unexpected error occoured!

For details, see /tmp/apparmor-bugreport-s93jfr8t.txt
Please consider reporting a bug at https://bugs.launchpad.net/apparmor/
and attach this file.

I send you kern.log file on email.
I noticed that sometimes aa-logprof doesn't see denied messages in logfile.

I don't have that /usr/lib/NetworkManager/nm-dhcp-client.action file and I dont have profile for it.

Comment 9 is a different bug, see https://launchpad.net/bugs/1525119 (already fixed in bzr). Since logparser.py got quite some fixes since the 2.10 release, try replacing your logparser.py with http://bazaar.launchpad.net/~apparmor-dev/apparmor/2.10/view/head:/utils/apparmor/logparser.py (I can't guarantee it's compatible with 2.10.0, but it should be)

For the /usr/lib/NetworkManager/nm-dhcp-client.action profile - it hides in your /etc/apparmor.d/sbin.dhclient ;-)

I found it. After split file on two different profiles aa-logprof still crashes.

I'm already downloaded branch version of apparmor and it's still doesn't see DENIED messages.

Which messages exactly?
(Please open a new bug for it, because that's totally unrelated to the crash reported here.)
(It can't be something with a strange log format, because aa-logprof understands your log in general.)

ok, I will do new bug report. But what about aa-logprof crashes from comment #12?

Depends on the exact traceback ;-) - I can only say that bzr trunk didn't crash anymore after applying the fix from comment 7.

I patched aa-.py (trunk version) but aa-logprof still crashes.

python3 ./aa-logprof -f /var/log/kern.log
Reading log entries from /var/log/kern.log.
Updating AppArmor profiles in /etc/apparmor.d.
Traceback (most recent call last):
  File "./aa-logprof", line 50, in <module>
    apparmor.do_logprof_pass(logmark)
  File "/usr/local/apparmor/utils/apparmor/aa.py", line 2176, in do_logprof_pass
    log = log_reader.read_log(logmark)
  File "/usr/local/apparmor/utils/apparmor/logparser.py", line 371, in read_log
    self.add_event_to_tree(event)
  File "/usr/local/apparmor/utils/apparmor/logparser.py", line 184, in add_event_to_tree
    e = self.parse_event_for_tree(e)
  File "/usr/local/apparmor/utils/apparmor/logparser.py", line 276, in parse_event_for_tree
    rmask = rmask.replace('c', 'a')
AttributeError: 'NoneType' object has no attribute 'replace'

An unexpected error occoured!

For details, see /tmp/apparmor-bugreport-tlzb_vya.txt
Please consider reporting a bug at https://bugs.launchpad.net/apparmor/

Hmm, this looks like you don't have the latest trunk checkout - this is bug 1525119 which is fixed since 2015-12-12.

Another detail confirms that you have an outdated checkout:
    rmask = rmask.replace('c', 'a')
We changed 'a' to 'w' a month ago ;-) (see bzr log -r3279 for background info)

Weird, I downloaded via bzr branch lp:apparmor command.

Workaround patch commited to trunk r 3380 and 2.10 branch r3317 - a failing serialize_profile_from_old_profile() (which will only happen if a file contains multiple profiles, so it's hopefully a corner case) will now print an error message that recommends the clean diff instead of crashing.

I have question:
In logs I see entries like

apparmor="ALLOWED" operation="file_inherit" profile="/usr/sbin/apache2//DEFAULT_URI//null-d5c" name="/dev/null" comm="sh" requested_mask="w" denied_mask="w" fsuid=33 ouid=0
or
apparmor="ALLOWED" operation="file_inherit" profile="/usr/sbin/apache2//DEFAULT_URI//null-d5c//null-d5d" name="/dev/null" comm="sendmail" requested_mask="w" denied_mask="w" fsuid=33 ouid=0

but there is no such profile like /usr/sbin/apache2//DEFAULT_URI//null-d5c.
Why this subprofiles (I don't know how to name this) appears in logs?

The null-* subprofiles are automatically created by the kernel if a program in complain mode executes another program, and there's no execute rule (ix, Px, Cx or Ux) for that yet.

There should be a line with operation="exec" some lines above the lines you pasted that show what exactly gets executed, but the comm= part can also give you a hint. In your examples, something in your DEFAULT_URI hat executes sh and sendmail, and both want to write something to /dev/null.

So can I ignore this entries if I profiling by hand?

Not really - they show that you also need some exec rules - probably something like
    /bin/sh ix,
    /usr/bin/sendmail Px,

Note that I guessed the directory names (only the program's filename is shown in the messages you provided), and that you'll need a separate profile for sendmail if you use Px.

You'll also need to allow "/dev/null w,", but if the profile has #include <abstractions/base>, it's already included there.

This bug was fixed in the package apparmor - 2.10.95-0ubuntu1

---------------
apparmor (2.10.95-0ubuntu1) xenial; urgency=medium

  * Update to apparmor 2.10.95 (2.11 Beta 1) (LP: #1561762)
    - Allow Apache prefork profile to chown(2) files (LP: #1210514)
    - Allow deluge-gtk and deluge-console to handle torrents opened in
      browsers (LP: #1501913)
    - Allow file accesses needed by some programs using libnl-3-200
      (Closes: #810888)
    - Allow file accesses needed on systems that use NetworkManager without
      resolvconf (Closes: #813835)
    - Adjust aa-status(8) to work without python3-apparmor (LP: #1480492)
    - Fix aa-logprof(8) crash when operating on files containing multiple
      profiles with certain rules (LP: #1528139)
    - Fix log parsing crashes, in the Python utilities, caused by certain file
      related events (LP: #1525119, LP: #1540562)
    - Fix log parsing crasher, in the Python utilities, caused by certain
      change_hat events (LP: #1523297)
    - Improve Python 2 support of the utils by fixing an aa-logprof(8) crasher
      when Python 3 is not available (LP: #1513880)
    - Send aa-easyprof(8) error messages to stderr instead of stdout
      (LP: #1521400)
    - Fix aa-autodep(8) failure when the shebang line of a script contained
      parameters (LP: #1505775)
    - Don't depend on the system logprof.conf when running utils/ build tests
      (LP: #1393979)
    - Fix apparmor_parser(8) bugs when parsing profiles that use policy
      namespaces in the profile declaration or profile transition targets
      (LP: #1540666, LP: #1544387)
    - Regression fix for apparmor_parser(8) bug that resulted in the
      --namespace-string commandline option being ignored causing profiles to
      be loaded into the root policy namespace (LP: #1526085)
    - Fix crasher regression in apparmor_parser(8) when the parser was asked
      to process a directory (LP: #1534405)
    - Fix bug in apparmor_parser(8) to honor the specified bind flags remount
      rules (LP: #1272028)
    - Support tarball generation for Coverity scans and fix a number of issues
      discovered by Coverity
    - Fix regression test failures on s390x systems (LP: #1531325)
    - Adjust expected errno values in changeprofile regression test
      (LP: #1559705)
    - The Python utils gained support for ptrace and signal rules
    - aa-exec(8) received a rewrite in C
    - apparmor_parser(8) gained support for stacking multiple profiles, as
      supported by the Xenial kernel (LP: #1379535)
    - libapparmor gained new public interfaces, aa_stack_profile(2) and
      aa_stack_onexec(2), allowing applications to utilize the new kernel
      stacking support (LP: #1379535)
  * Drop the following patches since they've been incorporated upstream:
    - aa-status-dont_require_python3-apparmor.patch
    - r3209-dnsmasq-allow-dash
    - r3227-locale-indep-capabilities-sorting.patch
    - r3277-update-python-abstraction.patch
    - r3366-networkd.patch,
    - tests-fix_sysctl_test.patch
    - parser-fix-cache-file-mtime-regression.patch
    - parser-verify-cache-file-mtime.patch
    - parser-run-caching-tests-without-apparmorfs.patch
    - pa...

For the records - I'm just working on a different implementation of "(V)iew Changes", which will also replace the workaround with a real fix :-) This will probably be in AppArmor 3.0, and will appear as merge request on gitlab this weekend.

Done - https://gitlab.com/apparmor/apparmor/merge_requests/131 will be part of AppArmor 3.0

Also backported to the 2.12 and 2.13 branch, will be in 2.12.2 and 2.13.2.