logparser doesn't understand /var/log/messages format

[Christian Boltz]

[impact]

This bug causes tools that use libapparmor to parse syslog and other
logs for apparmor rejections to fail to recognize apparmor events.

[steps to reproduce]

[regression potential]

The patch for this issue is confined to the log parsing portion of
the libapparmor library. Breakages occurring here would most likely
prevent tools that help assist the management of apparmor policy
from working; apparmor mediation would not be impacted. libapparmor
does provide other functionality, mostly around the aa_change_hat(3)
and aa_change_profile(3) calls; an entirely broken library could cause
issues for applications that make use of these from working correctly;
however, there are tests available in the upstream package that get
invoked by the lp:qa-regression-testing test-apparmor.py script that
ensure these continue to function.

[original description]

log parsing (part of libapparmor, used by aa-logprof and aa-genprof) doesn't understand the format in /var/log/messages, which means it doesn't find any events in it.

IIRC I've seen a similar report for the ubuntu syslog format on IRC.

Example log line from openSUSE:

2014-06-09T20:37:28.975070+02:00 geeko kernel: [21028.143765] type=1400 audit(1402339048.973:1421): apparmor="ALLOWED" operation="open" profile="/home/cb/linuxtag/apparmor/scripts/hello" name="/dev/tty" pid=14335 comm="hello" requested_mask="rw" denied_mask="rw" fsuid=1000 ouid=0

(Workaround: use auditd / audit.log)

[Christian Boltz (cboltz)]

This bug affects users on various distributions, see https://bugzilla.opensuse.org/show_bug.cgi?id=905368 and https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=771400 - the debian bugreport also contains some example log lines.

[Steve Beattie (sbeattie)]

Hi Christian,

I'm unable to reproduce this with your log entry and upstream libapparmor's test tool:

$ cat test_multi/testcase_syslog_lp1399027.in
2014-06-09T20:37:28.975070+02:00 geeko kernel: [21028.143765] type=1400 audit(1402339048.973:1421): apparmor="ALLOWED" operation="open" profile="/home/cb/linuxtag/apparmor/scripts/hello" name="/dev/tty" pid=14335 comm="hello" requested_mask="rw" denied_mask="rw" fsuid=1000 ouid=0
$ ./test_multi.multi test_multi/testcase_syslog_lp1399027.in
START
File: testcase_syslog_lp1399027.in
Event type: AA_RECORD_ALLOWED
Audit ID: 1402339048.973:1421
Operation: open
Mask: rw
Denied Mask: rw
fsuid: 1000
ouid: 0
Profile: /home/cb/linuxtag/apparmor/scripts/hello
Name: /dev/tty
Command: hello
PID: 14335
Epoch: 1402339048
Audit subid: 1421

which indicates libapparmor was successfully able to parse it.

[Christian Boltz (cboltz)]

I took the line from my own log (not from a bugreport), and you are right that it works :-/ - I'll need to search for a better example ;-)

However, a line from the debian bugreport fails for sure (just tested via py3 libapparmor bindings):

Dec 7 13:18:59 rosa kernel: audit: type=1400 audit(1417954745.397:82): apparmor="ALLOWED" operation="open" profile="/home/simi/bin/aa-test" name="/usr/bin/" pid=3231 comm="ls" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0

[Steve Beattie (sbeattie)]

Yeah, I'd gone on to try log entries from the debian bug report and was able to reproduce the failure. It's of course due to yet another syslog format. I have a patch in progress that I'm testing, but am thinking about how I can make the code that handles the vagaries of syslog formats less restrictive.

Thanks.

[Steve Beattie (sbeattie)]

For reference, to reproduce the issue in debian jessie, rsyslog needs to be replaced with syslog-ng as the syslog deamon.

A fix was committed for this in trunk rev 2830 and in apparmor 2.8 rev 2151.

[Steve Beattie (sbeattie)]

AppArmor 2.9.1 was released, closing.

[Andrew Clausen (clausen)]

(1) The fix doesn't work for me. Looking at the code, the fix is incomplete. It only fixes libraries/libapparmor/src/grammar.y, but we also need to fix ReadLog.RE_LOG_v2_6_syslog in utils/apparmor/logparserl.py needs to be updated to accommodate the extra "audit:" text, i.e. should be

    RE_LOG_v2_6_syslog = re.compile('kernel:\s+(\[[\d\.\s]+\]\s+)?audit:\stype=\d+\s+audit\([\d\.\:]+\):\s+apparmor=')

I don't see how the fix in 2.9.1 would have worked for anyone without this extra change.

(2) At this point, there are so many different syslog/audit formats that it might make sense to include some test cases, if not automated regression tests.

[Christian Boltz (cboltz)]

We still need to support the "old" syslog format, so we'll have to change the proposed regex to support both formats.

[Christian Boltz (cboltz)]

RE_LOG_v2_6_syslog = re.compile('kernel:\s+(\[[\d\.\s]+\]\s+)?(audit:\s+)?type=\d+\s+audit\([\d\.\:]+\):\s+apparmor=')
should work for both formats - I'll send the patch to the mailinglist for review.

[Christian Boltz (cboltz)]

Fix for logparser.py and some additional tests (test-logparser.py) commited to trunk and 2.9 branch. The 2.9.2 release will contain the fix.

[Steve Beattie (sbeattie)]

Attached is patch for the libapparmor portion of this bug for a trusty SRU. The python portion of this will be addressed in bug 1449769.

[Steve Beattie (sbeattie)]

I've reproduced the inability of libapparmor and the python apparmor utils to parse this log format in apparmor 2.8.95~2430-0ubuntu5.1 and have verified that the versions in apparmor 2.8.95~2430-0ubuntu5.2 in trusty-proposed fix the issue. Marking verification-done.

[Adam Conrad (adconrad)]

The verification of the Stable Release Update for apparmor has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Mathew Hodson (mhodson)]

This bug was fixed in the package apparmor - 2.8.95~2430-0ubuntu5.2

---------------
apparmor (2.8.95~2430-0ubuntu5.2) trusty-proposed; urgency=medium

  * debian/patches/php5-Zend_semaphore-lp1401084.patch: allow php5
    abstraction access to Zend opcache files (LP: #1401084)
  * debian/patches/dnsmasq-lxc_networking-lp1403468.patch: update
    profile for lxc support (LP: #1403468)
  * debian/patches/profiles-texlive_font_generation-lp1010909.patch:
    allow generation of texlive fonts by sanitized-helpers
    (LP: #1010909)
  * debian/apport/source_apparmor.py: fix the apparmor apport hook
    so it does not raise an exception if a non-unicode character is
    found in /var/log/kern.log or in /var/log/syslog. This should
    work under python3 or python2.7 (LP: #1304447)
  * debian/patches/profiles-dovecot-updates-lp1296667.patch: update
    dovecot profiles to address several missing permissions.
    (LP: #1296667)
  * debian/patches/profiles-adjust_X_for_lightdm-lp1339727.patch:
    adjust X abstraction for LightDM xauthority location (LP: #1339727)
  * debian/patches/libapparmor-fix_memory_leaks-lp1340927.patch; fix
    memory leaks in log parsing component of libapparmor (LP: #1340927)
  * debian/patches/libapparmor-another_audit_format-lp1399027.patch:
    add support for another log format style (LP: #1399027)
  * debian/patches/tests-workaround_for_unix_socket_change-lp1425398.patch:
    work around apparmor kernel behavioral change in regression tests
    (LP: #1425398)
  * debian/control: add breaks on python3-apparmor against older
    apparmor-utils that used to be where python bits lived
    (LP: #1373259)
  * debian/patches/utils-update_to_2.9.2.patch: update the python
    utilities to the upstream 2.9.2 (LP: #1449769, incorporating a
    large number of fixes and improvements, including:
    - fix aa-genprof traceback with apparmor 2.8.95 (LP: #1294797)
    - fix aa-genprof crashing when selecting scan on Ubuntu 14.04 server
      (LP: #1319829)
    - make aa-logprof read profile instead of program binary
      (LP: #1317176, LP: #1324154)
    - aa-complain: don't traceback when marking multiple profiles
      (LP: #1378095)
    - make python tools able to parse mounts with UTF-8 non-ascii
      characters (LP: #1310598)

 -- Steve Beattie <email address hidden> Thu, 30 Apr 2015 12:18:08 -0700

[cooloutac (cooloutac)]

Writing updated profile for /usr/bin/konversation.
Setting /usr/bin/konversation to complain mode.

Before you begin, you may wish to check if a
profile already exists for the application you
wish to confine. See the following wiki page for
more information:
http://wiki.apparmor.net/index.php/Profiles

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

Once completed, select the "Scan" option 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: /usr/bin/konversation

[(S)can system log for AppArmor events] / (F)inish
Reading log entries from /var/log/syslog.
Updating AppArmor profiles in /etc/apparmor.d.
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 402, in read_log
    self.add_event_to_tree(event)
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 206, in add_event_to_tree
    e = self.parse_event_for_tree(e)
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 303, in parse_event_for_tree
    raise AppArmorException(_('Log contains unknown mode %s') % rmask)
apparmor.common.AppArmorException: 'Log contains unknown mode senw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/sbin/aa-genprof", line 151, in <module>
    lp_ret = apparmor.do_logprof_pass(logmark, passno)
  File "/usr/lib/python3/dist-packages/apparmor/aa.py", line 2189, in do_logprof_pass
    log = log_reader.read_log(logmark)
  File "/usr/lib/python3/dist-packages/apparmor/logparser.py", line 407, in read_log
    raise AppArmorBug(ex_msg) # py3-only: from None
apparmor.common.AppArmorBug: Log contains unknown mode senw

This error was caused by the log line:
Jul 6 12:31:45 kernel: [ 1585.343460] audit: type=1400 audit(1467822705.150:668): apparmor="ALLOWED" operation="file_perm" profile="/usr/bin/konversation" pid=6877 comm="konversation" laddr=xxx.xxx.xxx.xxx lport=58236 faddr=164.132.77.237 fport=6697 family="inet" sock_type="stream" protocol=6 requested_mask="send" denied_mask="send"

[c0n7r4 (c0n7r4)]

Linux Mint is not parsing AppArmor complain log files correctly, I'm not sure why.

a sample from the audit.log file is
type=AVC msg=audit(1212212212.121:13867): apparmor="AUDIT" operation="open" profile="/usr/bin/testfile" name="/tmp/tempfile/" pid=2686 comm="testfile" requested_mask="r" fsuid=0 ouid=0

in the logparser.py file, it looks like it's getting picked up by the regex, and makes its way all the way to "def parse_event_for_tree(self, e):" where its stopped just a few lines in at:

"if aamode in ['UNKNOWN', 'AUDIT', 'STATUS', 'ERROR']: return None"

The aa-logprof run's without any fatal exceptions, just doesn't recognize any events.

[Christian Boltz (cboltz)]

> c0n7r4 (c0n7r4) wrote:
> apparmor="AUDIT"

AUDIT events happen if your profile has a rule like
    audit /tmp/tempfile/ r,
and the program is then really doing something that needs this rule (like getting a directory listing for /tmp/tempfile/).

"audit" means that the action is allowed (but gets logged every time), so there's nothing aa-logprof should ask about.

So for AUDIT events, aa-logprof works as expected - those things are already allowed, so there's nothing to ask ;-)