2.6.38.1 BUG

[moseleymark]

First off, a big thanks to you guys for getting the 2.6.38 patch out!

I'm getting this when the ACL system is enabled (if not enabled, it's fine). See this on both i386 (the trace below) and x86-64. The trace obviously looks different for x86-64 but the "kernel BUG" is at the same spot, gracl.c:1878. Once going, sometimes it'll go for a bit and other times will just spew and spew.

kernel: [ 347.152217] kernel BUG at grsecurity/gracl.c:1878!
kernel: [ 347.152217] invalid opcode: 0000 [#57] SMP
kernel: [ 347.152217] last sysfs file: /sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map
kernel: [ 347.152217] Modules linked in: dm_snapshot dm_mirror dm_region_hash dm_log dm_mod reiserfs joydev intel_agp intel_gtt i2c_i801 i2c_core agpgart evdev dcdbas i5000_edac i5k_amb hwmon button ide_cd_mod cdrom [last unloaded: scsi_wait_scan]
kernel: [ 347.152217]
kernel: [ 347.152217] Pid: 16491, comm: exim Tainted: G D 2.6.38.1-nx #1
kernel: [ 347.152217] Dell Inc. PowerEdge 1950/0DT097
kernel: [ 347.152217] EIP: 0060:[<0029c83d>] EFLAGS: 00010246 CPU: 3
kernel: [ 347.501343] EIP is at __chk_obj_label+0x47d/0x4f0
kernel: [ 347.501343] EAX: f4cc2888 EBX: 00000000 ECX: db18fa00 EDX: 00000003
kernel: [ 347.501343] ESI: 00000000 EDI: 00000001 EBP: e0bc7a78 ESP: e0bc7a30
kernel: [ 347.501343] DS: 0068 ES: 0068 FS: 00d8 GS: 007b SS: 0068
kernel: [ 347.501343] Process exim (pid: 16491, ti=e0bc6000 task=f1180cf0 task.ti=e0bc6000)
kernel: [ 347.501343] Stack:
kernel: [ 347.501343] db18c600 f2c2a840 f2b65680 00000000 00000067 00000014 000001b3 00000001
kernel: [ 347.501343] 01002000 f18f5b80 f2c2a840 00000000 00000000 00000000 00000001 f1180cf0
kernel: [ 347.501343] f2b65680 db18c600 e0bc7aa8 0029d2af 00000000 00000001 00000000 f2c2a840
kernel: [ 347.501343] Call Trace:
kernel: [ 347.501343] [<01002000>] ? 0x1002000
kernel: [ 347.501343] [<0029d2af>] gr_search_file+0x4f/0x180
kernel: [ 347.501343] [<00404010>] ? e1000_io_error_detected+0x60/0x70
kernel: [ 347.501343] [<002a238b>] gr_acl_handle_hidden_file+0x2b/0xb0
kernel: [ 347.501343] [<00124357>] link_path_walk+0x567/0xb20
kernel: [ 347.501343] [<005867e8>] ? xs_send_kvec+0xa8/0xb0
kernel: [ 347.501343] [<00273365>] ? skcipher_geniv_alloc+0x375/0x420
kernel: [ 347.501343] [<00124a17>] path_walk+0x47/0xa0
kernel: [ 347.501343] [<00124ad2>] vfs_path_lookup+0x62/0xc0
kernel: [ 347.501343] [<005833a1>] rpc_setup_pipedir+0x91/0x1a0
kernel: [ 347.501343] [<000e9208>] ? pcpu_alloc+0x6c8/0x840
kernel: [ 347.501343] [<0010935e>] ? __kmalloc+0xae/0x1b0
kernel: [ 347.501343] [<005834cf>] ? rpc_clone_client+0x1f/0x160
kernel: [ 347.501343] [<005998d1>] ? rpc_alloc_iostats+0x21/0x30
kernel: [ 347.501343] [<000080d0>] ? vector_used_by_percpu_irq+0x20/0x60
kernel: [ 347.501343] [<00583551>] rpc_clone_client+0xa1/0x160
kernel: [ 347.501343] [<001ee5d8>] nfs_init_server_rpcclient+0x28/0x110
kernel: [ 347.501343] [<001efb72>] nfs_clone_server+0xf2/0x270
kernel: [ 347.501343] [<00133a7c>] ? alloc_vfsmnt+0x8c/0x130
kernel: [ 347.501343] [<001fb120>] ? nfs_xdev_mount+0x0/0x240
kernel: [ 347.501343] [<001fb161>] nfs_xdev_mount+0x41/0x240
kernel: [ 347.501343] [<000e93af>] ? __alloc_percpu+0xf/0x20
kernel: [ 347.501343] [<001fb120>] ? nfs_xdev_mount+0x0/0x240
kernel: [ 347.501343] [<00118c8c>] vfs_kern_mount+0x5c/0x180
kernel: [ 347.501343] [<0020468b>] ? nfs_path+0xfb/0x130
kernel: [ 347.501343] [<0020498e>] nfs_d_automount+0x2ce/0x340
kernel: [ 347.501343] [<0012dc0a>] ? dput+0x8a/0x260
kernel: [ 347.501343] [<00020000>] ? mask_IO_APIC_setup+0x0/0xa0
kernel: [ 347.501343] [<001218f5>] follow_managed+0x155/0x1f0
kernel: [ 347.501343] [<008f4980>] ? 0x8f4980
kernel: [ 347.501343] [<00123044>] do_lookup+0x64/0x2a0
kernel: [ 347.501343] [<0012dc0a>] ? dput+0x8a/0x260
kernel: [ 347.501343] [<000705ea>] ? in_group_p+0x2a/0x30
kernel: [ 347.501343] [<00123f19>] link_path_walk+0x129/0xb20
kernel: [ 347.501343] [<000200da>] ? ioapic_resume+0x3a/0xd0
kernel: [ 347.501343] [<00124559>] link_path_walk+0x769/0xb20
kernel: [ 347.501343] [<00124b75>] do_path_lookup+0x45/0x140
kernel: [ 347.501343] [<0012599a>] user_path_at+0x4a/0x80
kernel: [ 347.501343] [<0011b3bf>] vfs_fstatat+0x4f/0x90
kernel: [ 347.501343] [<0011b480>] vfs_stat+0x20/0x30
kernel: [ 347.501343] [<0011b9e9>] sys_stat64+0x19/0x30
kernel: [ 347.501343] [<001216da>] ? path_put+0x1a/0x20
kernel: [ 347.501343] [<002aed6c>] ? trace_hardirqs_on_thunk+0xc/0x10
kernel: [ 347.501343] [<005ce260>] ? do_page_fault+0x0/0x720
kernel: [ 347.501343] [<002aed6c>] ? trace_hardirqs_on_thunk+0xc/0x10
kernel: [ 347.501343] [<005cad2d>] syscall_call+0x7/0xb
kernel: [ 347.501343] Code: c0 e8 38 d3 ff ff 89 45 08 90 8d 74 26 00 e9 23 ff ff ff 80 7d db 00 c7 45 f0 00 00 00 00 0f 85 e5 fc ff ff 66 90 e9 d8 fc ff ff <0f> 0b 90 eb fd 8b 45 0c 85 c0 90 0f 84 9a fd ff ff 8b 5e 14 85
kernel: [ 347.501343] EIP: [<0029c83d>] __chk_obj_label+0x47d/0x4f0 SS:ESP 0068:e0bc7a30
kernel: [ 349.363364] ---[ end trace 69f14e2b38391d0c ]---

[spender]

What was the last kernel this worked on? Have you changed your policy at all?

-Brad

[moseleymark]

These boxes (i.e. a 32-bit bos and 64-bit box) were both running a grsec'd 2.6.37.2 prior to 2.6.38.1. Both are Debian Lenny, both in this case Dell Poweredge 1950s.

As far as policy changes, I had to add "/sys h" to root's default to get the acl to load (and thus had to add some "/sys/... r" entries to irqbalance and sysstat). On both boxes syslog-ng was spewing mountains of errors initially about trying to append to /dev/tty* and /dev/ttyS*. I didn't have /dev in syslog-ng's ACL entry, as it was inheriting from root's default. As of 2.6.37.2, that was fine. So I added /dev and a bunch of things like /dev/tty* to syslog-ng's ACL entry. That has caused syslog-ng to stop squawking in 2.6.38.1.

[spender]

Can you show me the output of 'stat /' and also show the contents of /proc/mounts? (redact whatever you need to)
Also, can you try the 2.6.38.2 patch I just uploaded?

-Brad

[moseleymark]

From the 64-bit box:

# stat /
File: `/'
Size: 4096 Blocks: 8 IO Block: 4096 directory
Device: 803h/2051d Inode: 2 Links: 26
Access: (0755/drwxr-xr-x) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2011-03-28 12:00:22.000000000 -0400
Modify: 2010-10-25 19:25:19.000000000 -0400
Change: 2010-10-25 19:25:19.000000000 -0400

# cat /proc/mounts (heavily redacted, hopefully not *too* redacted)
rootfs / rootfs rw 0 0
none /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
none /proc proc rw,nosuid,nodev,noexec,relatime 0 0
none /dev devtmpfs rw,relatime,size=4085328k,nr_inodes=1021332,mode=755 0 0
none /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
/dev/sda3 / ext3 rw,relatime,errors=remount-ro,barrier=0,data=writeback 0 0
tmpfs /lib/init/rw tmpfs rw,nosuid,relatime,mode=755 0 0
tmpfs /dev/shm tmpfs rw,nosuid,nodev,relatime 0 0
/dev/sda1 /boot ext3 rw,relatime,errors=continue,barrier=0,data=writeback 0 0
/dev/sda4 /var ext3 rw,relatime,errors=continue,barrier=0,data=writeback 0 0
/dev/md1 /another/mount ext4 defaults,noatime 0 0
tmpfs /another/mount2 tmpfs rw,noatime 0 0
/dev/md2 /another/mount3 ext4 defaults,noatime 0 0
<dozens and dozens of identical NFS mounts, most of them submounts>


* On the 32-bit box, 2.6.38.2 does just fine. The level of activity is definitely lower at this time than earlier today when I was mucking with 2.6.38.1, so it's not impossible that it's time-related, though I doubt it (esp considering it was freaking out almost instantly after boot-up).

* On the 64-bit box, 2.6.38.2 does just fine too. One interesting thing (and I'm guessing it's *not* grsec-related but figured I should mention it in the very off-chance it is -- if not, off to the linux-nfs list) is that on the 64-bit box (and not that I can see on the 32-bit), in both 2.6.38.1 and 2.6.38.2, a shutdown hangs for a bit with this when it tries to umount the NFS mount with all the submounts:

[ 223.969514] kernel BUG at fs/dcache.c:947!
[ 223.970003] invalid opcode: 0000 [#1] SMP
[ 223.970003] last sysfs file: /sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map
[ 223.970003] CPU 4
[ 223.970003] Modules linked in: ipt_addrtype raid0 md_mod ioatdma dca power_meter loop joydev fan evdev psmouse i5000_edac dcdbas edac_core serio_raw ]
[ 223.970003]
[ 223.970003] Pid: 5633, comm: umount.nfs Not tainted 2.6.38.2 #1 Dell Inc. PowerEdge 1950/0DT097
[ 223.970003] RIP: 0010:[<ffffffff81154541>] [<ffffffff81154541>] shrink_dcache_for_umount_subtree+0x251/0x260
[ 223.970003] RSP: 0018:ffff88020c0f3d58 EFLAGS: 00010292
[ 223.970003] RAX: 000000000000006e RBX: ffff8802264fd71c RCX: 000000000001ffff
[ 223.970003] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffffffff81cf4830
[ 223.970003] RBP: ffff88020c0f3d88 R08: 0000000000000006 R09: 0000000000000000
[ 223.970003] R10: 0000000000000003 R11: 00000000ffffffff R12: ffff8802264fd6c0
[ 223.970003] R13: ffff88020e1b7240 R14: ffff88020e1b72e0 R15: ffff8802264fd71c
[ 223.970003] FS: 0000036e9afd06e0(0000) GS:ffff8800cfd00000(0000) knlGS:0000000000000000
[ 223.970003] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 223.970003] CR2: 000003b59f0a21d0 CR3: 000000000164a000 CR4: 00000000000006f0
[ 223.970003] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 223.970003] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 223.970003] Process umount.nfs (pid: 5633, threadinfo ffff88020c0f2000, task ffff880227e42e60)
[ 223.970003] Stack:
[ 223.970003] ffff8802253e6e58 ffff88022783b840 ffff88022783b89c ffff8802253e6c00
[ 223.970003] ffff8802253e6c00 0000000000000100 ffff88020c0f3db8 ffffffff811545b2
[ 223.970003] 0000000000000282 ffff8802253e6c00 ffff880225d6e000 ffffffff816bcc20
[ 223.970003] Call Trace:
[ 223.970003] [<ffffffff811545b2>] shrink_dcache_for_umount+0x62/0x80
[ 223.970003] [<ffffffff8113d35c>] generic_shutdown_super+0x2c/0x110
[ 223.970003] [<ffffffff8113d4d6>] kill_anon_super+0x16/0x60
[ 223.970003] [<ffffffff8123c485>] nfs_kill_super+0x25/0x40
[ 223.970003] [<ffffffff8113dc05>] deactivate_locked_super+0x55/0x70
[ 223.970003] [<ffffffff8113ebc9>] deactivate_super+0x79/0x80
[ 223.970003] [<ffffffff8115bb37>] mntput_no_expire+0x137/0x1b0
[ 223.970003] [<ffffffff8115bbcd>] mntput+0x1d/0x40
[ 223.970003] [<ffffffff8115bc61>] release_mounts+0x71/0x90
[ 223.970003] [<ffffffff8115c1c8>] sys_umount+0x308/0x3c0
[ 223.970003] [<ffffffff810030fb>] system_call_fastpath+0x16/0x1b
[ 223.970003] Code: 8b 45 30 48 85 c0 74 07 48 8b 90 a8 00 00 00 48 8d 86 58 02 00 00 48 c7 c7 20 c7 88 81 48 89 04 24 4c 89 ee 31 c0 e8 0d 0c 4c 00 <0
[ 223.970003] RIP [<ffffffff81154541>] shrink_dcache_for_umount_subtree+0x251/0x260
[ 223.970003] RSP <ffff88020c0f3d58>
[ 224.517005] ---[ end trace 544dea4b5f84f408 ]---

and makes it all the way to /sbin/halt (according to grsec exec_logging over serial) but then never actually reboots. I'm rolling a grsec-less 2.6.38.2 to see if it does that too.

[spender]

Seems to be a vanilla bug:

http://www.spinics.net/lists/linux-nfs/msg20232.html

-Brad

[moseleymark]

Yup, that looks like it. I figured it wasn't grsec-related.

Thanks, you saved me some google queries