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

Bug #1399027 reported by Christian Boltz on 2014-12-03
This bug affects 7 people
Affects Status Importance Assigned to Milestone
Steve Beattie
apparmor (Ubuntu)

Bug Description


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)

Revision history for this message
Christian Boltz (cboltz) wrote :

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.

Revision history for this message
Steve Beattie (sbeattie) wrote :

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
File: testcase_syslog_lp1399027.in
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.

Revision history for this message
Christian Boltz (cboltz) wrote :

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

Revision history for this message
Steve Beattie (sbeattie) wrote :

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.


Changed in apparmor:
status: New → In Progress
importance: Undecided → High
assignee: nobody → Steve Beattie (sbeattie)
milestone: none → 2.9.1
Revision history for this message
Steve Beattie (sbeattie) wrote :

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.

Changed in apparmor:
status: In Progress → Fix Committed
Revision history for this message
Steve Beattie (sbeattie) wrote :

AppArmor 2.9.1 was released, closing.

Changed in apparmor:
status: Fix Committed → Fix Released
Revision history for this message
Andrew Clausen (clausen) wrote :

(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) on 2015-01-16
Changed in apparmor:
status: Fix Released → Triaged
Revision history for this message
Christian Boltz (cboltz) wrote :

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

Revision history for this message
Christian Boltz (cboltz) wrote :

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.

Revision history for this message
Christian Boltz (cboltz) wrote :

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.

Changed in apparmor:
milestone: 2.9.1 → 2.9.2
status: Triaged → Fix Committed
Steve Beattie (sbeattie) on 2015-04-24
Changed in apparmor:
status: Fix Committed → Fix Released
Revision history for this message
Steve Beattie (sbeattie) wrote :

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.

description: updated
Revision history for this message
Steve Beattie (sbeattie) wrote :

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.

tags: added: verification-done
Revision history for this message
Adam Conrad (adconrad) wrote : Update Released

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.

Revision history for this message
Mathew Hodson (mhodson) wrote :

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

tags: added: aa-tools trusty utopic
Changed in apparmor (Ubuntu):
importance: Undecided → High
status: New → Fix Released
Revision history for this message
cooloutac (cooloutac) wrote :

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:

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
  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= fport=6697 family="inet" sock_type="stream" protocol=6 requested_mask="send" denied_mask="send"

Revision history for this message
c0n7r4 (c0n7r4) wrote :

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.

Revision history for this message
Christian Boltz (cboltz) wrote :

> 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 ;-)

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.