apparmor_parser: page allocation failure. order:5

Bug Description

Binary package hint: apparmor

Here is an abnormal kernel event caused by apparmor:

[266008.891973] type=1505 audit(1256022543.874:171): operation="profile_replace" pid=24071 name=/usr/bin/evince
[266008.893351] type=1505 audit(1256022543.878:172): operation="profile_replace" pid=24071 name=/usr/bin/evince-previewer
[266008.902321] apparmor_parser: page allocation failure. order:5, mode:0x40d0
[266008.902328] Pid: 24071, comm: apparmor_parser Not tainted 2.6.31-14-generic-pae #47-Ubuntu
[266008.902331] Call Trace:
[266008.902340] [<c057419e>] ? printk+0x18/0x1a
[266008.902347] [<c01ba2c0>] __alloc_pages_slowpath+0x340/0x480
[266008.902352] [<c01ba50f>] __alloc_pages_nodemask+0x10f/0x120
[266008.902356] [<c01ba567>] __get_free_pages+0x17/0x30
[266008.902361] [<c01e405f>] __kmalloc+0xdf/0x180
[266008.902381] [<c0488705>] unpack_table+0x85/0x140
[266008.902385] [<c048881e>] unpack_dfa+0x5e/0x100
[266008.902389] [<c048ae21>] aa_unpack_dfa+0x91/0xe0
[266008.902393] [<c048b350>] aa_unpack_profile+0x300/0x350
[266008.902397] [<c048b72e>] aa_interface_replace_profiles+0x7e/0x300
[266008.902402] [<c0486e64>] ? aa_simple_write_to_buffer+0x54/0xe0
[266008.902406] [<c0486f75>] aa_profile_replace+0x35/0x50
[266008.902411] [<c01eac4a>] vfs_write+0x9a/0x190
[266008.902415] [<c0486f40>] ? aa_profile_replace+0x0/0x50
[266008.902419] [<c01eb70d>] sys_write+0x3d/0x70
[266008.902423] [<c0103283>] sysenter_do_call+0x12/0x28
[266008.902426] Mem-Info:
[266008.902428] DMA per-cpu:
[266008.902431] CPU 0: hi: 0, btch: 1 usd: 0
[266008.902433] CPU 1: hi: 0, btch: 1 usd: 0
[266008.902435] Normal per-cpu:
[266008.902438] CPU 0: hi: 186, btch: 31 usd: 0
[266008.902440] CPU 1: hi: 186, btch: 31 usd: 59
[266008.902442] HighMem per-cpu:
[266008.902444] CPU 0: hi: 186, btch: 31 usd: 0
[266008.902447] CPU 1: hi: 186, btch: 31 usd: 0
[266008.902451] Active_anon:204500 active_file:63987 inactive_anon:119063
[266008.902453] inactive_file:63972 unevictable:716 dirty:907 writeback:0 unstable:0
[266008.902454] free:19470 slab:22878 mapped:17849 pagetables:4283 bounce:0
[266008.902459] DMA free:3592kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:3976kB inactive_file:876kB unevictable:0kB present:15848kB pages_scanned:0 all_unreclaimable? no
[266008.902463] lowmem_reserve[]: 0 867 2014 2014
[266008.902471] Normal free:71024kB min:3732kB low:4664kB high:5596kB active_anon:167824kB inactive_anon:237572kB active_file:112644kB inactive_file:130800kB unevictable:0kB present:887976kB pages_scanned:0 all_unreclaimable? no
[266008.902475] lowmem_reserve[]: 0 0 9179 9179
[266008.902481] HighMem free:3264kB min:512kB low:1744kB high:2980kB active_anon:650176kB inactive_anon:238680kB active_file:139328kB inactive_file:124212kB unevictable:2864kB present:1175008kB pages_scanned:0 all_unreclaimable? no
[266008.902486] lowmem_reserve[]: 0 0 0 0
[266008.902490] DMA: 26*4kB 24*8kB 48*16kB 11*32kB 2*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 3592kB
[266008.902502] Normal: 804*4kB 4624*8kB 1126*16kB 324*32kB 36*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 71024kB
[266008.902513] HighMem: 320*4kB 120*8kB 22*16kB 3*32kB 1*64kB 0*128kB 2*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3264kB
[266008.902525] 129875 total pagecache pages
[266008.902527] 0 pages in swap cache
[266008.902530] Swap cache stats: add 0, delete 0, find 0/0
[266008.902532] Free swap = 0kB
[266008.902533] Total swap = 0kB
[266008.912228] 523904 pages RAM
[266008.912231] 296066 pages HighMem
[266008.912233] 17032 pages reserved
[266008.912235] 173147 pages shared
[266008.912236] 397239 pages non-shared
[266008.919865] type=1505 audit(1256022543.902:173): operation="profile_replace" info="failed to unpack profile" pid=24071 name=/usr/bin/evince-thumbnailer

ProblemType: Bug
ApparmorStatusOutput:
Error: command /usr/sbin/apparmor_status failed with exit code 4: You do not have enough privilege to read the profile set.
apparmor module is loaded.
Architecture: i386
Date: Thu Oct 22 18:16:05 2009
DistroRelease: Ubuntu 9.10
Package: apparmor 2.3.1+1403-0ubuntu27 [modified: sbin/apparmor_parser]
ProcVersionSignature: Ubuntu 2.6.31-14.47-generic-pae
SourcePackage: apparmor
Uname: Linux 2.6.31-14-generic-pae i686

Here is the output of of the "apparmor_status " command, that ubuntu-bug was not allowed to execute:

root@vougeot:~# /usr/sbin/apparmor_status
apparmor module is loaded.
33 profiles are loaded.
12 profiles are in enforce mode.
/usr/share/gdm/guest-session/Xsession
/usr/sbin/avahi-daemon
/sbin/dhclient3
/usr/sbin/mysqld-akonadi
/usr/bin/evince-thumbnailer
/usr/sbin/cupsd
/usr/lib/NetworkManager/nm-dhcp-client.action
/usr/lib/connman/scripts/dhclient-script
/usr/bin/evince-previewer
/usr/sbin/tcpdump
/usr/lib/cups/backend/cups-pdf
/usr/bin/evince
21 profiles are in complain mode.
/usr/lib/dovecot/imap-login
/bin/ping
/usr/sbin/ntpd
/sbin/klogd
/sbin/syslogd
/sbin/syslog-ng
/usr/lib/dovecot/imap
/usr/sbin/traceroute
/usr/sbin/mdnsd
/usr/sbin/identd
/usr/lib/dovecot/managesieve-login
/usr/sbin/dnsmasq
/usr/sbin/nmbd
/usr/lib/dovecot/dovecot-auth
/usr/lib/dovecot/pop3-login
/usr/sbin/smbd
/usr/lib/dovecot/deliver
/usr/sbin/nscd
/usr/lib/dovecot/pop3
/usr/sbin/dovecot
/usr/sbin/named
5 processes have profiles defined.
4 processes are in enforce mode :
/usr/sbin/avahi-daemon (14468)
/sbin/dhclient3 (25344)
/usr/sbin/cupsd (14985)
/usr/sbin/avahi-daemon (14469)
1 processes are in complain mode.
/usr/sbin/ntpd (25722)
0 processes are unconfined but have a profile defined.

According to this comment (from another, but similar context):

http://lkml.indiana.edu/hypermail/linux/kernel/0606.0/0081.html

the problem is probably in the apparmor kernel patch. Allocating 5 continuous pages is a lot, especially after several days of uptime, such as in my case (laptop with many suspend/resume cycles). Therefore:

- either apparmor should try to use fewer pages or non continuous pages
- or it should try to allocate them on boot and keep them until shutdown

I have placed a test kernel with a fix at
http://kernel.ubuntu.com/~jj/linux-image-2.6.31-14-generic_2.6.31-14.48~jj_amd64.deb

Accepted linux into karmic-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

This bug was fixed in the package linux - 2.6.32-3.3

---------------
linux (2.6.32-3.3) lucid; urgency=low

[ Andy Whitcroft ]

* rebase to v2.6.32-rc6
* [Config] update configs following rebase to v2.6.32-rc6
* [Config] update ports configs following rebase to v2.6.32-rc6
* resync with Karmic Ubuntu-2.6.31-15.49
* [Config] add module ignores for broken drivers

[ John Johansen ]

* SAUCE: AppArmor: AppArmor wrongly reports allow perms as denied
- LP: #453335
* SAUCE: AppArmor: Policy load and replacement can fail to alloc mem
- LP: #458299
* SAUCE: AppArmor: AppArmor fails to audit change_hat correctly
- LP: #462824
* SAUCE: AppArmor: AppArmor disallows truncate of deleted files.
- LP: #451375

[ Kees Cook ]

* SAUCE: Fix nx_enable reporting
- LP: #454285

[ Scott James Remnant ]

* Revert "SAUCE: trace: add trace_event for the open() syscall"
* SAUCE: trace: add trace events for open(), exec() and uselib()
- LP: #462111

[ Stefan Bader ]

* SAUCE: Fix sub-flavour script to not stop on missing directories
- LP: #453073

[ Ubuntu Changes ]

* resync with Karmic Ubuntu-2.6.31-15.49

[ Upstream Kernel Changes ]

* rebase to v2.6.32-rc6
- LP: #464552
-- Andy Whitcroft <email address hidden> 2009年11月10日 15:00:57 +0000

On Fri, 2009年11月06日 at 09:49 +0000, Martin Pitt wrote:
>
> Accepted linux into karmic-proposed, the package will build now and be
> available in a few hours. Please test and give feedback here.

--
Laurent Bonnaud.
http://www.lis.inpg.fr/pages_perso/bonnaud/

On Fri, 2009年11月06日 at 09:49 +0000, Martin Pitt wrote:
>
> Accepted linux into karmic-proposed, the package will build now and be
> available in a few hours. Please test and give feedback here.

I installed linux-image-2.6.31-15-generic-pae and rebooted. After 2
days of uptime, the problem did not re-occur. But more uptime will
bring more confidence...

PS: sorry for my previous empty comment, caused by evolution's buggyness.

--
Laurent Bonnaud.
http://www.lis.inpg.fr/pages_perso/bonnaud/

This bug was fixed in the package linux - 2.6.31-15.50

---------------
linux (2.6.31-15.50) karmic-proposed; urgency=low

[ Kees Cook ]

* SAUCE: Fix nx_enable reporting
- LP: #454285

linux (2.6.31-15.49) karmic-proposed; urgency=low

[ Benjamin Herrenschmidt ]

* [Upstream] (drop after 2.6.31) usb-storage: Workaround devices with
bogus sense size
- LP: #446146

[ John Johansen ]

* SAUCE: AppArmor: AppArmor wrongly reports allow perms as denied
- LP: #453335
* SAUCE: AppArmor: Policy load and replacement can fail to alloc mem
- LP: #458299
* SAUCE: AppArmor: AppArmor fails to audit change_hat correctly
- LP: #462824
* SAUCE: AppArmor: AppArmor disallows truncate of deleted files.
- LP: #451375

[ Kees Cook ]

* SAUCE: [x86] fix report of cs-limit nx-emulation
- LP: #454285

[ Scott James Remnant ]

* Revert "SAUCE: trace: add trace_event for the open() syscall"
* SAUCE: trace: add trace events for open(), exec() and uselib()
- LP: #462111

[ Stefan Bader ]

* SAUCE: Fix sub-flavour script to not stop on missing directories
- LP: #453073

[ Tim Gardner ]

* [Upstream] (drop after 2.6.31) Input: synaptics - add another Protege
M300 to rate blacklist
- LP: #433801

[ Upstream Kernel Changes ]

* PM: Make warning in suspend_test_finish() less likely to happen
- LP: #464552
-- Stefan Bader <email address hidden> 2009年11月10日 14:31:52 +0100

It seems this bug or something very similar may have surfaced again. When a package postinst replaces an apparmor profile,

Jan 6 15:52:43 hapatus kernel: [103287.157730] apparmor_parser: page allocation failure. order:9, mode:0x40d0
Jan 6 15:52:43 hapatus kernel: [103287.178618] apparmor_parser: page allocation failure. order:7, mode:0x40d0

happens, and after that point, it seems a kernel process is taking all available CPU time to do something in an infinite loop, and all available RAM seems to be continuously allocated by the kernel.

Sorry, forgot to add information about my kernel:

Linux hapatus 2.6.32-9-generic-pae #13-Ubuntu SMP Thu Dec 17 17:03:19 UTC 2009 i686 GNU/Linux
ii linux-image-2.6.32-9-generic-pae 2.6.32-9.13 Linux kernel image for version 2.6.32 on x86

I am experiencing this in kernel: 2.6.31-19-generic #56-Ubuntu SMP

Attaching kernel log from a recent encounter with this bug.

Johan,

When package postinst replaces a profile there is a period where it goes through recompiling the policy that takes a lot of cpu and memory. How long the process takes depends on your processor and exact policy being recompiled but on slower processors this can take a minute or so, and can consume 100 MB while doing so.

Did the compilation process eventually complete for you or did truly enter an infinite loop and never complete. Also would it be possible to attach your kernel message log.

Johan,

never mind I missed it below DarkNova's comment, thanks.

DarkNova,

Can you attach your kernel message log (/var/log/kern.log), or out put of dmesg?

I have a 2.2 GHz dualcore AMD processor and three gigabytes of memory, most of which is always free.

Whenever an AppArmor update *doesn’t* hit this specific bug, it succeeds without using resources noticeably.

But whenever it does, the effect seems to be perpetual (until reboot), even after the AppArmor postinst has long since finished.

I haven't seen this error message, but apparmor upgrades (while installing a batch of updates) do cause a lot of thrashing on my system, which may have the same root cause. I can't reproduce it by running /etc/init.d/apparmor reload immediately after the upgrade is complete, though.

I just hit this myself, but don't have a reproducer yet. Others on irc have are seeing this as well. Adjusting Importance to 'High'.

there are a couple things going on here. The batch update recompiles the policy which is cpu intensive, more so as multiple profiles are being done in parallel. Once done, the compiled policy is cached in /etc/apparmor.d/cache/
We have discussed dropping the parallel compute part which would help reducing the load, and memory consumption

to replicate the compile load do
> sudo rm /etc/apparmor.d/cache/*
> sudo /etc/init.d/apparmor reload

The memory error message is simple bug where the __NO_WARN flag got missed on the fast path of a memory allocation, that falls back to a slower vmalloc when it fails.

The perpetual effect being reported by Johan is another bug that I haven't been able to rule out as being related to this bug yet.

This bug was fixed in the package linux - 2.6.32-19.28

---------------
linux (2.6.32-19.28) lucid; urgency=low

[ Andy Whitcroft ]

* [Config] enable various multitouch devices
- LP: #541453

[ Chase Douglas ]

* (pre-stable): input: ALPS - Add signature for HP Pavilion dm3 laptops
- LP: #545307
* SAUCE: Disable function tracing after hitting __schedule_bug
* SAUCE: Reduce ACPI resource conflict message to KERN_INFO, printf
cleanup
- LP: #440470

[ Jesse Barnes ]

* SAUCE: drm/i915: don't change DRM configuration when releasing load
detect pipe
- LP: #488328

[ John Johansen ]

* SAUCE: AppArmor: Remove null_profile's use of PFLAG_NO_LIST_REF
- LP: #539437
* SAUCE: AppArmor: Stop page allocation warnings that can occur on policy
load
- LP: #458299
* SAUCE: AppArmor: Return string len rather than the allocation size
- LP: #551844
* SAUCE: AppArmor: Fix oops in profile verification if profile unpack
fails.

[ Luke Yelavich ]

* [Config] Enable Nouveau DRM module on powerpc

[ Stefan Bader ]

* SAUCE: Pull in thinkpad-acpi from v2.6.34-rc1
- LP: #357673
* [Config] Enable thinkpad-acpi ALSA volume control
- LP: #357673

[ Steve Conklin ]

* SAUCE: drm/i915: Disable FBC on 915GM and 945GM
- LP: #492392, #539609

[ Upstream Kernel Changes ]

* Revert "(pre-stable) drm/i915: blacklist lid status: Sony VGN-BX196VP,
Dell Inspiron 700m"
- LP: #515246
* (pre-stable) softlockup: Stop spurious softlockup messages due to
overflow
- LP: #551068
* backlight: mbp_nvidia_bl - add five more MacBook variants
- LP: #511965
* drm/nv04-nv40: Fix up the programmed horizontal sync pulse delay.
- LP: #529130
* drm/nouveau: Fix fbcon corruption with font width not divisible by 8
- LP: #544739
* (pre-stable) USB: fix usbfs regression
* drm/radeon/bo: add some fallback placements for VRAM only objects.
- LP: #507148
* drm/radeon/kms: don't print error on -ERESTARTSYS.
- LP: #507148
* Input: add the ABS_MT_PRESSURE event
- LP: #541453
* HID: Support for 3M multitouch panel
- LP: #541453
* HID: make 3M PCT touchscreen driver standalone config option
- LP: #541453
* HID: add support for Stantum multitouch panel
- LP: #541453
* HID: make Stantum driver standalone config option
- LP: #541453
* HID: add support for Acer T230H multitouch
- LP: #541453
* HID: add support for Pixart Imaging Optical Touch Screen
- LP: #541453
* HID: fixed bug in single-touch emulation on the stantum panel
- LP: #541453
* HID: add pressure support for the Stantum multitouch panel
- LP: #541453
* HID: Support for MosArt multitouch panel
- LP: #541453
* HID: hid-ntrig add multi input quirk and clean up
- LP: #541453
* HID: n-trig: remove unnecessary tool switching
- LP: #541453
* HID: hid-ntrig: multitouch cleanup and fix
- LP: #541453
* HID: hid-ntrig: Single touch mode tap
- LP: #541453
* hid: ntrig touch events
- LP: #541453
* (pre-stable) x86-32, resume: do a global tlb flush in S4 resume
- LP: #531309
* drm/i915: Part of: Add initial bits for VGA mode...