Random kernel warnings when running apache with mod_apparmor

[Michael Mönch]

I am running Ubuntu 14.04.2 with libapache2-mod-apparmor 2.8.95 and apache 2.4.7 (mpm_prefork). At random intervals I get kernel-warnings triggered in kref.h:47 like the following:

[45589.839473] ------------[ cut here ]------------
[45589.839548] WARNING: CPU: 1 PID: 1526 at /build/buildd/linux-lts-utopic-3.16.0/include/linux/kref.h:47 kref_get.part.0+0x1e/0x27()
[45589.839552] Modules linked in: cirrus ttm drm_kms_helper drm syscopyarea sysfillrect sysimgblt joydev ppdev i2c_piix4 pvpanic mac_hid serio_raw parport_pc lp parport hid_generic usbhid hid floppy psmouse pata_acpi e1000
[45589.839676] CPU: 1 PID: 1526 Comm: apache2 Not tainted 3.16.0-34-generic #47~14.04.1-Ubuntu
[45589.839680] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5.1-0-g8936dbb-20141113_115728-nilsson.home.kraxel.org 04/01/2014
[45589.839684] 0000000000000009 ffff8800b909bc28 ffffffff8176432f 0000000000000000
[45589.839691] ffff8800b909bc60 ffffffff8106dd9d ffff880036b87f80 ffff880036b87f80
[45589.839696] ffff880138af2030 ffff880036a41c30 ffff8800ba9d2f00 ffff8800b909bc70
[45589.839702] Call Trace:
[45589.839712] [<ffffffff8176432f>] dump_stack+0x45/0x56
[45589.839749] [<ffffffff8106dd9d>] warn_slowpath_common+0x7d/0xa0
[45589.839757] [<ffffffff8106de7a>] warn_slowpath_null+0x1a/0x20
[45589.839762] [<ffffffff81764037>] kref_get.part.0+0x1e/0x27
[45589.839802] [<ffffffff8132fe75>] aa_label_merge+0x445/0x7c0
[45589.839811] [<ffffffff8132cc32>] update_file_cxt+0x32/0x80
[45589.839818] [<ffffffff8132d842>] aa_file_perm+0x112/0x430
[45589.839824] [<ffffffff8132abaa>] common_file_perm+0x4a/0x100
[45589.839830] [<ffffffff8132adb8>] apparmor_file_permission+0x18/0x20
[45589.839847] [<ffffffff812eb003>] security_file_permission+0x23/0xa0
[45589.839879] [<ffffffff811d3ff2>] rw_verify_area+0x52/0xd0
[45589.839886] [<ffffffff811d517d>] do_readv_writev+0x6d/0x240
[45589.839919] [<ffffffff81054eaf>] ? kvm_clock_get_cycles+0x1f/0x30
[45589.839936] [<ffffffff810d906a>] ? __getnstimeofday+0x3a/0xc0
[45589.839943] [<ffffffff811d53d9>] vfs_writev+0x39/0x50
[45589.839950] [<ffffffff811d550a>] SyS_writev+0x4a/0xd0
[45589.839963] [<ffffffff8176ca6d>] system_call_fastpath+0x1a/0x1f
[45589.839967] ---[ end trace 6bc65d507855f6b2 ]---

I am not able to reproduce these warnings by accessing Apache myself. It only happens at random intervals during the normal operation of the webserver.

[Roger Lehmann (roger-lehmann-u)]

A similar problem appeared yesterday. This time the whole VM froze until it was being hard restarted with the qm command line tool.
This is a serious problem for high availability VMs.

[414592.904138] BUG: unable to handle kernel NULL pointer dereference at 0000000000000098
[414592.904370] IP: [<ffffffff8132fa77>] aa_label_merge+0x47/0x7c0
[414592.904491] PGD 0
[414592.904518] Oops: 0000 [#1] SMP
[414592.904573] Modules linked in: cirrus ttm drm_kms_helper drm syscopyarea sysfillrect sysimgblt joydev ppdev i2c_piix4 pvpanic mac_hid serio_raw parport_pc lp parport hid_generic usbhid hid floppy psmouse pata_acpi e1000
[414592.904848] CPU: 1 PID: 10822 Comm: apache2 Tainted: G W 3.16.0-34-generic #47~14.04.1-Ubuntu
[414592.904948] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5.1-0-g8936dbb-20141113_115728-nilsson.home.kraxel.org 04/01/2014
[414592.905083] task: ffff88001a559460 ti: ffff8800b9f88000 task.ti: ffff8800b9f88000
[414592.905162] RIP: 0010:[<ffffffff8132fa77>] [<ffffffff8132fa77>] aa_label_merge+0x47/0x7c0
[414592.905271] RSP: 0018:ffff8800b9f8bd50 EFLAGS: 00010297
[414592.905328] RAX: 0000000000000000 RBX: 0000000000000020 RCX: 0000000000000001
[414592.905402] RDX: 0000000000000020 RSI: ffff880138af2030 RDI: ffff88010df5cc80
[414592.905477] RBP: ffff8800b9f8bda8 R08: 0000000000000006 R09: ffff8800b9b8b800
[414592.905551] R10: ffff8800b9f8bcd0 R11: ffff8800b9f8bc78 R12: ffff88010df5cc80
[414592.905632] R13: ffff88010df5cc80 R14: ffff880138af2030 R15: 0000000000000000
[414592.905710] FS: 00007f0e14825780(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
[414592.905794] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[414592.905855] CR2: 0000000000000098 CR3: 00000000b9d5a000 CR4: 00000000000006e0
[414592.905947] Stack:
[414592.905972] ffff8800b9b8b800 0000000000000000 ffff8800b9b8b800 0000000000000000
[414592.906059] ffff8800b9f8bda8 ffffffff81334219 ffff88001936bf40 ffff88010df5cc80
[414592.906146] ffff880138af2030 0000000000000004 0000000000000000 ffff8800b9f8bdd8
[414592.906246] Call Trace:
[414592.906281] [<ffffffff81334219>] ? aa_label_sk_perm.isra.2+0x99/0x110
[414592.906354] [<ffffffff8132cc32>] update_file_cxt+0x32/0x80
[414592.906416] [<ffffffff8132d842>] aa_file_perm+0x112/0x430
[414592.906506] [<ffffffff816b4fa8>] ? tcp_rcv_state_process+0x388/0xf30
[414592.906587] [<ffffffff8164b5e8>] ? sk_reset_timer+0x18/0x30
[414592.906652] [<ffffffff816b7265>] ? tcp_schedule_loss_probe+0x145/0x1e0
[414592.906725] [<ffffffff8132abaa>] common_file_perm+0x4a/0x100
[414592.906789] [<ffffffff816be8ca>] ? tcp_v4_do_rcv+0x2aa/0x4c0
[414592.906853] [<ffffffff8132adb8>] apparmor_file_permission+0x18/0x20
[414592.906936] [<ffffffff812eb003>] security_file_permission+0x23/0xa0
[414592.907030] [<ffffffff811d3ff2>] rw_verify_area+0x52/0xd0
[414592.907093] [<ffffffff811d40dd>] vfs_read+0x6d/0x170
[414592.907150] [<ffffffff811d4d86>] SyS_read+0x46/0xb0
[414592.907250] [<ffffffff811e9325>] ? SyS_poll+0x65/0x100
[414592.907280] [<ffffffff8176ca6d>] system_call_fastpath+0x1a/0x1f
[414592.907303] Code: ec 30 48 85 ff 0f 84 30 06 00 00 4d 85 f6 0f 84 64 07 00 00 4d 39 f5 0f 84 92 04 00 00 41 8b ...

[Roger Lehmann (roger-lehmann-u)]

I just noticed that my problem is not directly the same as the original bug report, therefore I created a separate bug report at https://bugs.launchpad.net/apparmor/+bug/1448912