6:38 p.m.
Yet another leak - this time it seems to be the audit_socketcall()
in sys_socketcall().
When I did this, the laptop had been up for about 16 hours, with no network
connectivity. There were about 400K size-32 slab entries outstanding then - later
on it was well over 1.2M after some more uptime.
dmesg -s 16000000 | grep ' obj ' 1 | cut -f2 -d: | sort | uniq -c | sort -nr |
head
199154 c02e72b2 <sys_socketcall+0x4d/0x186>
8412 c01da799 <cond_insertf+0xb5/0x10d>
4949 c01d5007 <ebitmap_read+0xc1/0x1ce>
2136 c01d52b2 <hashtab_insert+0x64/0xc3>
1873 c01d795f <policydb_read+0x2b9/0xbbe>
1454 c01d72ea <type_read+0x1e/0xde>
698 c01cf596 <selinux_file_alloc_security+0x25/0x47>
(Meta-question - why am I tripping over all these leaks?)
1:18 p.m.
On Sunday 05 March 2006 19:38, Valdis.Kletnieks(a)vt.edu wrote:
Yet another leak - this time it seems to be the audit_socketcall()
in sys_socketcall().
I've been looking through the code and don't see the leak. audit_free_context
calls audit_free_aux which appears to do the right thing. Does anyone else
see the leak?
(Meta-question - why am I tripping over all these leaks?)
Cause no one else is testing like you. How are you finding the leaks? More
people could watch for these if you tell us what you are doing. BTW, thanks
for pointing them out.
-Steve
2:18 p.m.
On Mon, 06 Mar 2006 14:18:47 EST, Steve Grubb said:
On Sunday 05 March 2006 19:38, Valdis.Kletnieks(a)vt.edu wrote:
> Yet another leak - this time it seems to be the audit_socketcall()
> in sys_socketcall().
I've been looking through the code and don't see the leak. audit_free_context
calls audit_free_aux which appears to do the right thing. Does anyone else
see the leak?
I wonder if the problem is that audit_free_context() never gets hit for some
things. I didn't get warm and fuzzies about the fact that *all* calls to
sys_socketcall() end up hitting it - a few lines later we have a huge switch:
case SYS_SOCKET:
case SYS_BIND:
case SYS_CONNECT:
case SYS_LISTEN:
case SYS_ACCEPT:
case SYS_GETSOCKNAME:
case SYS_GETPEERNAME:
case SYS_SOCKETPAIR:
case SYS_SEND:
case SYS_SENDTO:
case SYS_RECV:
case SYS_RECVFROM:
case SYS_SHUTDOWN:
case SYS_SETSOCKOPT:
case SYS_GETSOCKOPT:
case SYS_SENDMSG:
case SYS_RECVMSG:
default:
Does one of these paths manage to escape hitting the cleanup, because it doesn't
do anything that's LSPP auditable?
> (Meta-question - why am I tripping over all these leaks?)
Cause no one else is testing like you. How are you finding the leaks? More
people could watch for these if you tell us what you are doing. BTW, thanks
for pointing them out.
I build the kernel on my laptop, I boot it, and after a few hours, I see
a growing number in /proc/meminfo for slab, and a matching odd entry in
/proc/slabinfo. That's why I don't understand why I've hit 3 leaks of
this magnitude - is everybody else testing this code running it for just
short tests on BHI (Big Honkin' Iron) hardware, rather than trying to stay
up for a weekend on a laptop class box?
I've been up and running for an hour, and I got this:
% grep size-32 /proc/slabinfo
size-32 118052 118104 44 84 1 : tunables 32 16 0 : slabdata
1406 1406 0 : globalstat 138932 118052 1407 1 0 1 0 0 :
cpustat 640001 9763 530408 1305
% echo "size-32 0 0 0" >| /proc/slabinfo
% dmesg -c -s 16000000 > /tmp/f2
% ls -l /tmp/f2
8736 -rw-r--r-- 1 root root 8929222 Mar 6 14:36 /tmp/f2
% grep ' obj ' /tmp/f2 | cut -f2 -d: | sort | uniq -c | sort -nr | head
105187 c02e72b2 <sys_socketcall+0x4d/0x186>
8412 c01da799 <cond_insertf+0xb5/0x10d>
4949 c01d5007 <ebitmap_read+0xc1/0x1ce>
2136 c01d52b2 <hashtab_insert+0x64/0xc3>
1873 c01d795f <policydb_read+0x2b9/0xbbe>
1454 c01d72ea <type_read+0x1e/0xde>
1153 c01cf596 <selinux_file_alloc_security+0x25/0x47>
353 c0151a85 <cache_alloc_refill+0x35c/0x59f>
288 c01d67e0 <perm_read+0x1e/0xcf>
268 c018c5c4 <sysfs_create_link+0x4a/0xda>
And in the 20 minutes I spent composing this mail, it's grown:
% grep size-32 /proc/slabinfo
size-32 146496 146496 44 84 1 : tunables 32 16 0 : slabdata
1744 1744 0 : globalstat 168336 146496 1745 1 0 1 0 0 :
cpustat 779819 11855 643828 1365
Yowza.
11:27 a.m.
On Sun, 05 Mar 2006 19:38:28 EST, Valdis.Kletnieks(a)vt.edu said:
Yet another leak - this time it seems to be the audit_socketcall()
in sys_socketcall().
199154 c02e72b2 <sys_socketcall+0x4d/0x186>
Still present in 2.6.16-rc6-mm1:
% grep socket /proc/slab_allocators
size-1024: 3 yenta_probe+0x40/0x49f [yenta_socket]
size-64: 354 audit_socketcall+0x3e/0x84
size-32: 108634 audit_socketcall+0x3e/0x84
Uptime of just over an hour. However, this one might not be audit's fault -
looks like there's something else leaking, and this is just along for the ride:
% grep inode /proc/slab_allocators
mqueue_inode_cache: 1 mqueue_alloc_inode+0x12/0x14
ext3_inode_cache: 13280 ext3_alloc_inode+0x12/0x41
shmem_inode_cache: 418 shmem_alloc_inode+0x12/0x1f
sock_inode_cache: 138577 sock_alloc_inode+0x12/0x51
proc_inode_cache: 403 proc_alloc_inode+0x16/0x67
bdev_cache: 33 bdev_alloc_inode+0x12/0x22
inode_cache: 967 alloc_inode+0x26/0x17a
size-2048: 10 journal_init_inode+0x81/0x118
size-512: 2 journal_init_inode+0x81/0x118
size-64: 153679 selinux_inode_alloc_security+0x25/0x71
Lots of sock_alloc_inode's left dangling, which is probably dragging the
selinux_inode_alloc_security and audit context along with it.
lsof | grep sock | wc -l says there's only 62 sockets open on the system.
Looks like time to go wade through and figure out where the sock_alloc_inode
stuff is going astray. Yee. Hah.
12:59 a.m.
On Wed, 15 Mar 2006 12:27:17 EST, Valdis.Kletnieks(a)vt.edu said:
On Sun, 05 Mar 2006 19:38:28 EST, Valdis.Kletnieks(a)vt.edu said:
> Yet another leak - this time it seems to be the audit_socketcall()
> in sys_socketcall().
> 199154 c02e72b2 <sys_socketcall+0x4d/0x186>
Still present in 2.6.16-rc6-mm1:
% grep socket /proc/slab_allocators
size-1024: 3 yenta_probe+0x40/0x49f [yenta_socket]
size-64: 354 audit_socketcall+0x3e/0x84
size-32: 108634 audit_socketcall+0x3e/0x84
Uptime of just over an hour. However, this one might not be audit's fault -
looks like there's something else leaking, and this is just along for the ride:
This leak was still present in 2.6.16-mm1, and I had a long free evening, so
I chased it down. Unfortunately, the cause isn't very pretty at all, but may
explain all the multiple problem's I've seen...
Here's what's happening:
strace of /usr/bin/Xorg shows *lots* of these:
getsockopt(20, SOL_SOCKET, SO_PEERCRED, "8\n\0\0\307\3\0\0\307\3\0\0", [12]) =
0
and each of these hits audit_socketcall(), which does a kalloc(). And it's
doing this multiple times a second, so we eventually have several hundred
thousand aux entries created by audit_socketcall(),
Unfortunately, we never actually call audit_free_aux() on these suckers in a
timely fashion - eventually, we go nuts and free zillions of entries:
Mar 25 01:03:01 turing-police kernel: [ 1862.036000] audit: freed 18870 aux entries
Mar 25 01:03:01 turing-police kernel: [ 1862.036000] <c0103aeb> show_trace+0xd/0xf
<c0103b8c> dump_stack+0x17/0x19
Mar 25 01:03:01 turing-police kernel: [ 1862.036000] <c0130646>
audit_syscall_exit+0x38f/0x3c7 <c010505c> do_syscall_trace+0x60/0x16e
Mar 25 01:03:01 turing-police kernel: [ 1862.040000] <c01027d6>
syscall_exit_work+0x12/0x18
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] audit: freed 6785 aux entries
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c0103aeb> show_trace+0xd/0xf
<c0103b8c> dump_stack+0x17/0x19
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c0130fb8>
audit_free+0x204/0x238 <c011220a> __put_task_struct+0x8c/0xf
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c011442b>
delayed_put_task_struct+0x3b/0x42 <c0122878> __rcu_process_callbacks+0x121/0x177
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c01228e0>
rcu_process_callbacks+0x12/0x23 <c01179a5> tasklet_action+0x3a/0x60
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c011791f>
__do_softirq+0x43/0x8f <c01047ad> do_softirq+0x47/0x52
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] =======================
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c0117c19> ksoftirqd+0x74/0xe3
<c012461c> kthread+0x97/0xc4
Mar 25 01:12:59 turing-police kernel: [ 2460.180000] <c0100ac9>
kernel_thread_helper+0x5/0xb
Mar 25 01:13:00 turing-police kernel: [ 2460.880000] audit: freed 48848 aux entries
Mar 25 01:13:00 turing-police kernel: [ 2460.880000] <c0103aeb> show_trace+0xd/0xf
<c0103b8c> dump_stack+0x17/0x19
Mar 25 01:13:00 turing-police kernel: [ 2460.880000] <c0130fb8>
audit_free+0x204/0x238 <c011220a> __put_task_struct+0x8c/0xf1
Mar 25 01:13:00 turing-police kernel: [ 2460.884000] <c011442b>
delayed_put_task_struct+0x3b/0x42 <c0122878> __rcu_process_callbacks+0x121/0x177
Mar 25 01:13:00 turing-police kernel: [ 2460.884000] <c01228e0>
rcu_process_callbacks+0x12/0x23 <c01179a5> tasklet_action+0x3a/0x60
Mar 25 01:13:00 turing-police kernel: [ 2460.884000] <c011791f>
__do_softirq+0x43/0x8f <c01047ad> do_softirq+0x47/0x52
Mar 25 01:13:00 turing-police kernel: [ 2460.884000] =======================
Mar 25 01:13:00 turing-police kernel: [ 2460.884000] <c0117a3f> irq_exit+0x30/0x3c
<c0104759> do_IRQ+0x7a/0x87
Mar 25 01:13:00 turing-police kernel: [ 2460.888000] <c01030ae>
common_interrupt+0x1a/0x20
(I'm not sure what precipitated the kfree of 18K entries. The 6K and 48K ones
came out of restarting the X server...)
I think the problem is that we get into audit_syscall_exit() and hit this:
/* Not having a context here is ok, since the parent may have
* called __put_task_struct. */
if (likely(!context))
goto out;
and we bail, leaving the memory pending till some later time. If that goto doesn't
get
us, then we hit this:
if (context->auditable)
audit_log_exit(context, GFP_KERNEL);
which may be the source of the audit message flood I've seen - we suddenly dump
out not only *this* syscall's log entry, but also the previous 45,948 or so aux
entries that we haven't gotten around to freeing. Looks like on my box, these
only get freed when a process exits, or we generate an AVC.
And since I have selinux in "permissive" mode at the moment, we only generate
an avc the first time we hit something - and as a result, after the first 15-20
minutes of uptime, we generate avc's very rarely, so those aux entries pile up
at the rate of about 2K/minute.
I strongly suspect the dentry references kept by the AUDIT_AVC_PATH code that
finally get freed by the dput() in audit_free_aux are why I was also seeing the
leaking sock_inode_cache and selinux_inode_alloc_security slab allocations...
Unfortunately, I'm not sufficiently confident on either my analysis or what the
code is *supposed* to be doing to actually propose a patch. However, I'm
*hoping* I'm right, because it would explain 100% of the issues I'm still
seeeing with the audit code...
Comments, anybody?
Here's the debugging patch I was using:
--- linux-2.6.16-mm1/kernel/auditsc.c.lkml2 2006-03-24 23:00:08.000000000 -0500
+++ linux-2.6.16-mm1/kernel/auditsc.c 2006-03-24 23:34:34.000000000 -0500
@@ -415,6 +415,7 @@ static inline void audit_free_names(stru
static inline void audit_free_aux(struct audit_context *context)
{
struct audit_aux_data *aux;
+ int count = 0;
while ((aux = context->aux)) {
if (aux->type == AUDIT_AVC_PATH) {
@@ -430,6 +431,11 @@ static inline void audit_free_aux(struct
context->aux = aux->next;
kfree(aux);
+ count++;
+ }
+ if (count >= 50) {
+ printk(KERN_INFO "audit: freed %d aux entries\n",count);
+ dump_stack();
}
}
4:12 p.m.
On Saturday 25 March 2006 01:59, Valdis.Kletnieks(a)vt.edu wrote:
This leak was still present in 2.6.16-mm1, and I had a long free
evening,
so I chased it down. Unfortunately, the cause isn't very pretty at all,
but may explain all the multiple problem's I've seen...
We've dropped the performance patch from the audit git tree for the time
being. I don't know if Andrew has refreshed his tree against the audit git
tree so that its dropped in his kernels, too.
I don't know if the performance patch was causing all your problems. But it
would be a worthwhile test to see if the lspp.14 kernel still has this
problem. The lspp.14 kernel is better for us to troubleshoot since we know
exactly what patches are applied to it.
Thanks,
-Steve
12:53 a.m.
On Mon, 27 Mar 2006 17:12:59 EST, Steve Grubb said:
We've dropped the performance patch from the audit git tree for
the time
being. I don't know if Andrew has refreshed his tree against the audit git
tree so that its dropped in his kernels, too.
2.6.16-mm1 has this version in it:
-rw-r--r-- akpm/akpm 135621 2006-03-22 17:08:47 broken-out/git-audit-master.patch
GIT f8becdcc22146fa7462c0a67a12d37d32bc15855
git+ssh://master.kernel.org/pub/scm/linux/kernel/git/viro/audit-current.g...
The most recent patch in that tree is Al Viro's March 10 fix for a leak
in audit_inode_context.
I don't know if the performance patch was causing all your
problems. But it
would be a worthwhile test to see if the lspp.14 kernel still has this
problem. The lspp.14 kernel is better for us to troubleshoot since we know
exactly what patches are applied to it.
OK, I'm willing to check into that - where's the lspp.14 hiding? It seems
that David Woodhouse's site stopped around lspp.10 or so.
5:19 a.m.
On Tuesday 28 March 2006 01:53, Valdis.Kletnieks(a)vt.edu wrote:
OK, I'm willing to check into that - where's the lspp.14
hiding? It seems
that David Woodhouse's site stopped around lspp.10 or so.
The lspp.14 kernel is published to the lspp yum repo at:
http://people.redhat.com/sgrubb/files/lspp. This should be the location for
all current lspp work.
-Steve
12:08 p.m.
On Tue, 28 Mar 2006 06:19:04 EST, Steve Grubb said:
On Tuesday 28 March 2006 01:53, Valdis.Kletnieks(a)vt.edu wrote:
> OK, I'm willing to check into that - where's the lspp.14 hiding? It seems
> that David Woodhouse's site stopped around lspp.10 or so.
The lspp.14 kernel is published to the lspp yum repo at:
http://people.redhat.com/sgrubb/files/lspp. This should be the location for
all current lspp work.
OK, I grabbed kernel-2.6.16-1.2074.2.2_FC5.lspp.14.src.rpm and will report
back (probably tomorrow-ish)...
6843
days inactive
6865
days old
linux-audit@lists.linux-audit.osci.io
8 comments
2 participants
participants (2)
-
Steve Grubb -
Valdis.Kletnieks＠vt.edu