Fix a number of problems with the new key garbage collector:
(1) A rogue semicolon in keyring_gc() was causing the initial count of dead
keys to be miscalculated.
(2) A missing return in keyring_gc() meant that under certain circumstances,
the keyring semaphore would be unlocked twice.
(3) The key serial tree iterator (key_garbage_collector()) part of the garbage
collector has been modified to:
(a) Complete each scan of the keyrings before setting the new timer.
(b) Only set the new timer for keys that have yet to expire. This means
that the new timer is now calculated correctly, and the gc doesn't
get into a loop continually scanning for keys that have expired, and
preventing other things from happening, like RCU cleaning up the old
keyring contents.
(c) Perform an extra scan if any keys were garbage collected in this one
as a key might become garbage during a scan, and (b) could mean we
don't set the timer again.
(4) Made key_schedule_gc() take the time at which to do a collection run,
rather than the time at which the key expires. This means the collection
of dead keys (key type unregistered) can happen immediately.
Signed-off-by: David Howells <[email protected]>
---
security/keys/gc.c | 78 +++++++++++++++++++++++++++++++----------------
security/keys/key.c | 4 +-
security/keys/keyctl.c | 2 +
security/keys/keyring.c | 24 +++++++++++---
4 files changed, 73 insertions(+), 35 deletions(-)
diff --git a/security/keys/gc.c b/security/keys/gc.c
index 1e616ae..485fc62 100644
--- a/security/keys/gc.c
+++ b/security/keys/gc.c
@@ -26,8 +26,10 @@ static void key_garbage_collector(struct work_struct *);
static DEFINE_TIMER(key_gc_timer, key_gc_timer_func, 0, 0);
static DECLARE_WORK(key_gc_work, key_garbage_collector);
static key_serial_t key_gc_cursor; /* the last key the gc considered */
+static bool key_gc_again;
static unsigned long key_gc_executing;
static time_t key_gc_next_run = LONG_MAX;
+static time_t key_gc_new_timer;
/*
* Schedule a garbage collection run
@@ -40,9 +42,7 @@ void key_schedule_gc(time_t gc_at)
kenter("%ld", gc_at - now);
- gc_at += key_gc_delay;
-
- if (now >= gc_at) {
+ if (gc_at <= now) {
schedule_work(&key_gc_work);
} else if (gc_at < key_gc_next_run) {
expires = jiffies + (gc_at - now) * HZ;
@@ -112,16 +112,18 @@ static void key_garbage_collector(struct work_struct *work)
struct rb_node *rb;
key_serial_t cursor;
struct key *key, *xkey;
- time_t new_timer = LONG_MAX, limit;
+ time_t new_timer = LONG_MAX, limit, now;
- kenter("");
+ now = current_kernel_time().tv_sec;
+ kenter("[%x,%ld]", key_gc_cursor, key_gc_new_timer - now);
if (test_and_set_bit(0, &key_gc_executing)) {
- key_schedule_gc(current_kernel_time().tv_sec);
+ key_schedule_gc(current_kernel_time().tv_sec + 1);
+ kleave(" [busy; deferring]");
return;
}
- limit = current_kernel_time().tv_sec;
+ limit = now;
if (limit > key_gc_delay)
limit -= key_gc_delay;
else
@@ -129,12 +131,19 @@ static void key_garbage_collector(struct work_struct *work)
spin_lock(&key_serial_lock);
- if (RB_EMPTY_ROOT(&key_serial_tree))
- goto reached_the_end;
+ if (unlikely(RB_EMPTY_ROOT(&key_serial_tree))) {
+ spin_unlock(&key_serial_lock);
+ clear_bit(0, &key_gc_executing);
+ return;
+ }
cursor = key_gc_cursor;
if (cursor < 0)
cursor = 0;
+ if (cursor > 0)
+ new_timer = key_gc_new_timer;
+ else
+ key_gc_again = false;
/* find the first key above the cursor */
key = NULL;
@@ -160,35 +169,50 @@ static void key_garbage_collector(struct work_struct *work)
/* trawl through the keys looking for keyrings */
for (;;) {
- if (key->expiry > 0 && key->expiry < new_timer)
+ if (key->expiry > now && key->expiry < new_timer) {
+ kdebug("will expire %x in %ld",
+ key_serial(key), key->expiry - now);
new_timer = key->expiry;
+ }
if (key->type == &key_type_keyring &&
- key_gc_keyring(key, limit)) {
- /* the gc ate our lock */
- schedule_work(&key_gc_work);
- goto no_unlock;
- }
+ key_gc_keyring(key, limit))
+ /* the gc had to release our lock so that the keyring
+ * could be modified, so we have to get it again */
+ goto gc_released_our_lock;
rb = rb_next(&key->serial_node);
- if (!rb) {
- key_gc_cursor = 0;
- break;
- }
+ if (!rb)
+ goto reached_the_end;
key = rb_entry(rb, struct key, serial_node);
}
-out:
- spin_unlock(&key_serial_lock);
-no_unlock:
+gc_released_our_lock:
+ kdebug("gc_released_our_lock");
+ key_gc_new_timer = new_timer;
+ key_gc_again = true;
clear_bit(0, &key_gc_executing);
- if (new_timer < LONG_MAX)
- key_schedule_gc(new_timer);
-
- kleave("");
+ schedule_work(&key_gc_work);
+ kleave(" [continue]");
return;
+ /* when we reach the end of the run, we set the timer for the next one */
reached_the_end:
+ kdebug("reached_the_end");
+ spin_unlock(&key_serial_lock);
+ key_gc_new_timer = new_timer;
key_gc_cursor = 0;
- goto out;
+ clear_bit(0, &key_gc_executing);
+
+ if (key_gc_again) {
+ /* there may have been a key that expired whilst we were
+ * scanning, so if we discarded any links we should do another
+ * scan */
+ new_timer = now + 1;
+ key_schedule_gc(new_timer);
+ } else if (new_timer < LONG_MAX) {
+ new_timer += key_gc_delay;
+ key_schedule_gc(new_timer);
+ }
+ kleave(" [end]");
}
diff --git a/security/keys/key.c b/security/keys/key.c
index 08531ad..e50d264 100644
--- a/security/keys/key.c
+++ b/security/keys/key.c
@@ -500,7 +500,7 @@ int key_negate_and_link(struct key *key,
set_bit(KEY_FLAG_INSTANTIATED, &key->flags);
now = current_kernel_time();
key->expiry = now.tv_sec + timeout;
- key_schedule_gc(key->expiry);
+ key_schedule_gc(key->expiry + key_gc_delay);
if (test_and_clear_bit(KEY_FLAG_USER_CONSTRUCT, &key->flags))
awaken = 1;
@@ -909,7 +909,7 @@ void key_revoke(struct key *key)
time = now.tv_sec;
if (key->revoked_at == 0 || key->revoked_at > time) {
key->revoked_at = time;
- key_schedule_gc(key->revoked_at);
+ key_schedule_gc(key->revoked_at + key_gc_delay);
}
up_write(&key->sem);
diff --git a/security/keys/keyctl.c b/security/keys/keyctl.c
index 60983f3..2fb28ef 100644
--- a/security/keys/keyctl.c
+++ b/security/keys/keyctl.c
@@ -1115,7 +1115,7 @@ long keyctl_set_timeout(key_serial_t id, unsigned timeout)
}
key->expiry = expiry;
- key_schedule_gc(key->expiry);
+ key_schedule_gc(key->expiry + key_gc_delay);
up_write(&key->sem);
key_put(key);
diff --git a/security/keys/keyring.c b/security/keys/keyring.c
index ac977f6..8ec0274 100644
--- a/security/keys/keyring.c
+++ b/security/keys/keyring.c
@@ -1019,18 +1019,18 @@ void keyring_gc(struct key *keyring, time_t limit)
struct key *key;
int loop, keep, max;
- kenter("%x", key_serial(keyring));
+ kenter("{%x,%s}", key_serial(keyring), keyring->description);
down_write(&keyring->sem);
klist = keyring->payload.subscriptions;
if (!klist)
- goto just_return;
+ goto no_klist;
/* work out how many subscriptions we're keeping */
keep = 0;
for (loop = klist->nkeys - 1; loop >= 0; loop--)
- if (!key_is_dead(klist->keys[loop], limit));
+ if (!key_is_dead(klist->keys[loop], limit))
keep++;
if (keep == klist->nkeys)
@@ -1041,7 +1041,7 @@ void keyring_gc(struct key *keyring, time_t limit)
new = kmalloc(sizeof(struct keyring_list) + max * sizeof(struct key *),
GFP_KERNEL);
if (!new)
- goto just_return;
+ goto nomem;
new->maxkeys = max;
new->nkeys = 0;
new->delkey = 0;
@@ -1081,7 +1081,21 @@ void keyring_gc(struct key *keyring, time_t limit)
discard_new:
new->nkeys = keep;
keyring_clear_rcu_disposal(&new->rcu);
+ up_write(&keyring->sem);
+ kleave(" [discard]");
+ return;
+
just_return:
up_write(&keyring->sem);
- kleave(" [no]");
+ kleave(" [no dead]");
+ return;
+
+no_klist:
+ up_write(&keyring->sem);
+ kleave(" [no_klist]");
+ return;
+
+nomem:
+ up_write(&keyring->sem);
+ kleave(" [oom]");
}
This is an updated pull request, with David's latest patches incorporated.
(The previous pull url still works, this is branched from that with the
new patches added).
Please pull this if you haven't pulled the other one already.
The following changes since commit 86d710146fb9975f04c505ec78caa43d227c1018:
Linus Torvalds (1):
Merge git://git.linux-nfs.org/projects/trondmy/nfs-2.6
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/jmorris/security-testing-2.6 for-linus2
David Howells (2):
CRED: Allow put_cred() to cope with a NULL groups list
KEYS: Fix garbage collector
Eric Paris (3):
Creds: creds->security can be NULL is selinux is disabled
SELinux: seperate avc_cache flushing
SELinux: flush the avc before disabling SELinux
Marc Dionne (1):
KEYS: Unlock tasklist when exiting early from keyctl_session_to_parent
include/linux/cred.h | 13 ++++---
include/linux/selinux.h | 9 +++++
kernel/cred.c | 3 +-
security/keys/gc.c | 78 ++++++++++++++++++++++++++++---------------
security/keys/key.c | 4 +-
security/keys/keyctl.c | 3 +-
security/keys/keyring.c | 24 +++++++++++---
security/selinux/avc.c | 26 +++++++++++----
security/selinux/exports.c | 6 +++
9 files changed, 118 insertions(+), 48 deletions(-)
--
James Morris
<[email protected]>
On Tue, 15 Sep 2009, James Morris wrote:
>
> Please pull this if you haven't pulled the other one already.
No. This is entirely broken. I get about a million
include/linux/selinux.h:92: warning: ?selinux_is_enabled? defined but not used
warnings. Very annoying.
Linus
On Mon, 2009-09-14 at 17:37 -0700, Linus Torvalds wrote:
>
> On Tue, 15 Sep 2009, James Morris wrote:
> >
> > Please pull this if you haven't pulled the other one already.
>
> No. This is entirely broken. I get about a million
>
> include/linux/selinux.h:92: warning: ‘selinux_is_enabled’ defined but not used
>
> warnings. Very annoying.
grummble grummble, forgot the 'inline' in the !CONFIG_SECURITY_SELINUX
for selinux_is_enabled in selinux.h.....
one line patch upcoming.
-Eric
i'm still getting crashes even with latest -git [0cb583f]:
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly on device 8:6.
async_waiting @ 1
async_continuing @ 1 after 0 usec
debug: unmapping init memory ffffffff81f1e000..ffffffff81fb1000
SELinux: Disabled at runtime.
BUG: unable to handle kernel NULL pointer dereference at (null)
IP: [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
PGD 0
Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
last sysfs file:
CPU 1
Modules linked in:
Pid: 12, comm: khelper Not tainted 2.6.31-tip-05525-g0eeacc6-dirty #14819 System Product Name
RIP: 0010:[<ffffffff81122537>] [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
RSP: 0018:ffff88003f9258b0 EFLAGS: 00010086
RAX: 0000000000000001 RBX: 0000000000000000 RCX: 0000000078c0129e
RDX: 0000000000000000 RSI: ffffffff8130b626 RDI: ffffffff81122528
RBP: ffff88003f925900 R08: 0000000078c0129e R09: 0000000000000001
R10: 0000000000000000 R11: 0000000078c0129e R12: 0000000000000246
R13: 0000000000008020 R14: ffff88003f8586d8 R15: 0000000000000001
FS: 0000000000000000(0000) GS:ffff880002b00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 0000000001001000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: ffffffff827bd420 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process khelper (pid: 12, threadinfo ffff88003f924000, task ffff88003f928000)
Stack:
0000000000000246 0000802000000246 ffffffff8130b626 0000000000000001
<0> 0000000078c0129e 0000000000000000 ffff88003f925a70 0000000000000002
<0> 0000000000000001 0000000000000001 ffff88003f925960 ffffffff8130b626
Call Trace:
[<ffffffff8130b626>] ? avc_alloc_node+0x36/0x273
[<ffffffff8130b626>] avc_alloc_node+0x36/0x273
[<ffffffff8130b545>] ? avc_latest_notif_update+0x7d/0x9e
[<ffffffff8130b8b4>] avc_insert+0x51/0x18d
[<ffffffff8130bcce>] avc_has_perm_noaudit+0x9d/0x128
[<ffffffff8130bf20>] avc_has_perm+0x45/0x88
[<ffffffff8130f99d>] current_has_perm+0x52/0x6d
[<ffffffff8130fbb2>] selinux_task_create+0x2f/0x45
[<ffffffff81303bf7>] security_task_create+0x29/0x3f
[<ffffffff8105c6ba>] copy_process+0x82/0xdf0
[<ffffffff81091578>] ? register_lock_class+0x2f/0x36c
[<ffffffff81091a13>] ? mark_lock+0x2e/0x1e1
[<ffffffff8105d596>] do_fork+0x16e/0x382
[<ffffffff81091578>] ? register_lock_class+0x2f/0x36c
[<ffffffff810d9166>] ? probe_workqueue_execution+0x57/0xf9
[<ffffffff81091a13>] ? mark_lock+0x2e/0x1e1
[<ffffffff810d9166>] ? probe_workqueue_execution+0x57/0xf9
[<ffffffff8100cdb2>] kernel_thread+0x82/0xe0
[<ffffffff81078b1f>] ? ____call_usermodehelper+0x0/0x139
[<ffffffff8100ce10>] ? child_rip+0x0/0x20
[<ffffffff81078aea>] ? __call_usermodehelper+0x65/0x9a
[<ffffffff8107a5c7>] run_workqueue+0x171/0x27e
[<ffffffff8107a573>] ? run_workqueue+0x11d/0x27e
[<ffffffff81078a85>] ? __call_usermodehelper+0x0/0x9a
[<ffffffff8107a7bc>] worker_thread+0xe8/0x10f
[<ffffffff810808e2>] ? autoremove_wake_function+0x0/0x63
[<ffffffff8107a6d4>] ? worker_thread+0x0/0x10f
[<ffffffff8108042e>] kthread+0x91/0x99
[<ffffffff8100ce1a>] child_rip+0xa/0x20
[<ffffffff8100c754>] ? restore_args+0x0/0x30
[<ffffffff8108039d>] ? kthread+0x0/0x99
[<ffffffff8100ce10>] ? child_rip+0x0/0x20
Code: 0f 85 99 00 00 00 9c 58 66 66 90 66 90 49 89 c4 fa 66 66 90 66 66 90 e8 83 34 fb ff e8 d7 e9 26 00 48 98 49 8b 94 c6 10 01 00 00 <48> 8b 1a 44 8b 7a 18 48 85 db 74 0f 8b 42 14 48 8b 04 c3 ff 42
RIP [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
RSP <ffff88003f9258b0>
CR2: 0000000000000000
---[ end trace 42f41a982344e606 ]---
Kernel panic - not syncing: Fatal exception
config and full crashlog attached as well.
Ingo
On Wed, 2009-09-16 at 15:02 +0200, Ingo Molnar wrote:
> i'm still getting crashes even with latest -git [0cb583f]:
This is something totally different, not quite sure since my system
doesn't reproduce it. It's doesn't look like the problem I ran into
where SLUB couldn't call kmem_cache_destroy at all. I'll build with
your config. I have an idea, I assume this is an SMP machine?
-Eric
> EXT3-fs: mounted filesystem with ordered data mode.
> VFS: Mounted root (ext3 filesystem) readonly on device 8:6.
> async_waiting @ 1
> async_continuing @ 1 after 0 usec
> debug: unmapping init memory ffffffff81f1e000..ffffffff81fb1000
> SELinux: Disabled at runtime.
> BUG: unable to handle kernel NULL pointer dereference at (null)
> IP: [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
> PGD 0
> Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> last sysfs file:
> CPU 1
> Modules linked in:
> Pid: 12, comm: khelper Not tainted 2.6.31-tip-05525-g0eeacc6-dirty #14819 System Product Name
> RIP: 0010:[<ffffffff81122537>] [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
> RSP: 0018:ffff88003f9258b0 EFLAGS: 00010086
> RAX: 0000000000000001 RBX: 0000000000000000 RCX: 0000000078c0129e
> RDX: 0000000000000000 RSI: ffffffff8130b626 RDI: ffffffff81122528
> RBP: ffff88003f925900 R08: 0000000078c0129e R09: 0000000000000001
> R10: 0000000000000000 R11: 0000000078c0129e R12: 0000000000000246
> R13: 0000000000008020 R14: ffff88003f8586d8 R15: 0000000000000001
> FS: 0000000000000000(0000) GS:ffff880002b00000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
> CR2: 0000000000000000 CR3: 0000000001001000 CR4: 00000000000006e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: ffffffff827bd420 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> Process khelper (pid: 12, threadinfo ffff88003f924000, task ffff88003f928000)
> Stack:
> 0000000000000246 0000802000000246 ffffffff8130b626 0000000000000001
> <0> 0000000078c0129e 0000000000000000 ffff88003f925a70 0000000000000002
> <0> 0000000000000001 0000000000000001 ffff88003f925960 ffffffff8130b626
> Call Trace:
> [<ffffffff8130b626>] ? avc_alloc_node+0x36/0x273
> [<ffffffff8130b626>] avc_alloc_node+0x36/0x273
> [<ffffffff8130b545>] ? avc_latest_notif_update+0x7d/0x9e
> [<ffffffff8130b8b4>] avc_insert+0x51/0x18d
> [<ffffffff8130bcce>] avc_has_perm_noaudit+0x9d/0x128
> [<ffffffff8130bf20>] avc_has_perm+0x45/0x88
> [<ffffffff8130f99d>] current_has_perm+0x52/0x6d
> [<ffffffff8130fbb2>] selinux_task_create+0x2f/0x45
> [<ffffffff81303bf7>] security_task_create+0x29/0x3f
> [<ffffffff8105c6ba>] copy_process+0x82/0xdf0
> [<ffffffff81091578>] ? register_lock_class+0x2f/0x36c
> [<ffffffff81091a13>] ? mark_lock+0x2e/0x1e1
> [<ffffffff8105d596>] do_fork+0x16e/0x382
> [<ffffffff81091578>] ? register_lock_class+0x2f/0x36c
> [<ffffffff810d9166>] ? probe_workqueue_execution+0x57/0xf9
> [<ffffffff81091a13>] ? mark_lock+0x2e/0x1e1
> [<ffffffff810d9166>] ? probe_workqueue_execution+0x57/0xf9
> [<ffffffff8100cdb2>] kernel_thread+0x82/0xe0
> [<ffffffff81078b1f>] ? ____call_usermodehelper+0x0/0x139
> [<ffffffff8100ce10>] ? child_rip+0x0/0x20
> [<ffffffff81078aea>] ? __call_usermodehelper+0x65/0x9a
> [<ffffffff8107a5c7>] run_workqueue+0x171/0x27e
> [<ffffffff8107a573>] ? run_workqueue+0x11d/0x27e
> [<ffffffff81078a85>] ? __call_usermodehelper+0x0/0x9a
> [<ffffffff8107a7bc>] worker_thread+0xe8/0x10f
> [<ffffffff810808e2>] ? autoremove_wake_function+0x0/0x63
> [<ffffffff8107a6d4>] ? worker_thread+0x0/0x10f
> [<ffffffff8108042e>] kthread+0x91/0x99
> [<ffffffff8100ce1a>] child_rip+0xa/0x20
> [<ffffffff8100c754>] ? restore_args+0x0/0x30
> [<ffffffff8108039d>] ? kthread+0x0/0x99
> [<ffffffff8100ce10>] ? child_rip+0x0/0x20
> Code: 0f 85 99 00 00 00 9c 58 66 66 90 66 90 49 89 c4 fa 66 66 90 66 66 90 e8 83 34 fb ff e8 d7 e9 26 00 48 98 49 8b 94 c6 10 01 00 00 <48> 8b 1a 44 8b 7a 18 48 85 db 74 0f 8b 42 14 48 8b 04 c3 ff 42
> RIP [<ffffffff81122537>] kmem_cache_alloc+0x9a/0x185
> RSP <ffff88003f9258b0>
> CR2: 0000000000000000
> ---[ end trace 42f41a982344e606 ]---
> Kernel panic - not syncing: Fatal exception
>
> config and full crashlog attached as well.
>
> Ingo
* Eric Paris <[email protected]> wrote:
> On Wed, 2009-09-16 at 15:02 +0200, Ingo Molnar wrote:
> > i'm still getting crashes even with latest -git [0cb583f]:
>
> This is something totally different, not quite sure since my system
> doesn't reproduce it. It's doesn't look like the problem I ran into
> where SLUB couldn't call kmem_cache_destroy at all. I'll build with
> your config. I have an idea, I assume this is an SMP machine?
Correct - as can be seen in the full bootlog i have attached to my
report.
Ingo
here's a new failure mode i havent seen before (possibly a variation of
the others):
[ 20.036058] Freeing unused kernel memory: 1332k freed
[ 20.316099] SELinux: Disabled at runtime.
[ 20.320059] =============================================================================
[ 20.324029] BUG avc_node: Objects remaining on kmem_cache_close()
[ 20.324029] -----------------------------------------------------------------------------
[ 20.324029]
[ 20.324029] INFO: Slab 0xffffea0000de4230 objects=30 used=9 fp=0xffff88003f80a4c8 flags=0x4000000000000082
[ 20.324029] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
[ 20.324029] Call Trace:
[ 20.324029] [<ffffffff810de4ba>] slab_err+0xb0/0xd2
[ 20.324029] [<ffffffff810dfa58>] list_slab_objects+0xa8/0x14e
[ 20.324029] [<ffffffff810e2d48>] kmem_cache_destroy+0x108/0x1d8
[ 20.324029] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
[ 20.324029] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
[ 20.324029] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
[ 20.324029] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
[ 20.324029] [<ffffffff810e6a37>] sys_write+0x5b/0x98
[ 20.324029] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
[ 20.324029] INFO: Object 0xffff88003f80a000 @offset=0
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5072 cpu=0 pid=0
[ 20.324029] INFO: Object 0xffff88003f80a088 @offset=136
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5055 cpu=0 pid=0
[ 20.324029] INFO: Object 0xffff88003f80a110 @offset=272
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4981 cpu=0 pid=6
[ 20.324029] INFO: Object 0xffff88003f80a198 @offset=408
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4229 cpu=0 pid=1
[ 20.324029] INFO: Object 0xffff88003f80a220 @offset=544
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
[ 20.324029] INFO: Object 0xffff88003f80a2a8 @offset=680
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
[ 20.324029] INFO: Object 0xffff88003f80a330 @offset=816
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=89 cpu=0 pid=1
[ 20.324029] INFO: Object 0xffff88003f80a3b8 @offset=952
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=57 cpu=0 pid=1
[ 20.324029] INFO: Object 0xffff88003f80a440 @offset=1088
[ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=48 cpu=0 pid=1
[ 20.324031] SLUB avc_node: kmem_cache_destroy called for cache that still has objects.
[ 20.328031] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
[ 20.332031] Call Trace:
[ 20.334489] [<ffffffff810e2db7>] kmem_cache_destroy+0x177/0x1d8
[ 20.336032] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
[ 20.340033] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
[ 20.344032] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
[ 20.348032] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
[ 20.352032] [<ffffffff810e6a37>] sys_write+0x5b/0x98
[ 20.356033] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
[ 20.368209] SELinux: Unregistering netfilter hooks
[ 20.372051] type=1404 audit(1253208317.372:2): selinux=0 auid=4294967295 ses=4294967295
Config attached.
Ingo
On Thu, 2009-09-17 at 17:19 +0200, Ingo Molnar wrote:
> here's a new failure mode i havent seen before (possibly a variation of
> the others):
>
> [ 20.036058] Freeing unused kernel memory: 1332k freed
> [ 20.316099] SELinux: Disabled at runtime.
> [ 20.320059] =============================================================================
> [ 20.324029] BUG avc_node: Objects remaining on kmem_cache_close()
> [ 20.324029] -----------------------------------------------------------------------------
> [ 20.324029]
> [ 20.324029] INFO: Slab 0xffffea0000de4230 objects=30 used=9 fp=0xffff88003f80a4c8 flags=0x4000000000000082
> [ 20.324029] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> [ 20.324029] Call Trace:
> [ 20.324029] [<ffffffff810de4ba>] slab_err+0xb0/0xd2
> [ 20.324029] [<ffffffff810dfa58>] list_slab_objects+0xa8/0x14e
> [ 20.324029] [<ffffffff810e2d48>] kmem_cache_destroy+0x108/0x1d8
> [ 20.324029] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> [ 20.324029] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> [ 20.324029] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> [ 20.324029] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> [ 20.324029] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> [ 20.324029] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> [ 20.324029] INFO: Object 0xffff88003f80a000 @offset=0
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5072 cpu=0 pid=0
> [ 20.324029] INFO: Object 0xffff88003f80a088 @offset=136
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5055 cpu=0 pid=0
> [ 20.324029] INFO: Object 0xffff88003f80a110 @offset=272
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4981 cpu=0 pid=6
> [ 20.324029] INFO: Object 0xffff88003f80a198 @offset=408
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4229 cpu=0 pid=1
> [ 20.324029] INFO: Object 0xffff88003f80a220 @offset=544
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> [ 20.324029] INFO: Object 0xffff88003f80a2a8 @offset=680
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> [ 20.324029] INFO: Object 0xffff88003f80a330 @offset=816
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=89 cpu=0 pid=1
> [ 20.324029] INFO: Object 0xffff88003f80a3b8 @offset=952
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=57 cpu=0 pid=1
> [ 20.324029] INFO: Object 0xffff88003f80a440 @offset=1088
> [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=48 cpu=0 pid=1
> [ 20.324031] SLUB avc_node: kmem_cache_destroy called for cache that still has objects.
> [ 20.328031] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> [ 20.332031] Call Trace:
> [ 20.334489] [<ffffffff810e2db7>] kmem_cache_destroy+0x177/0x1d8
> [ 20.336032] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> [ 20.340033] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> [ 20.344032] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> [ 20.348032] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> [ 20.352032] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> [ 20.356033] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> [ 20.368209] SELinux: Unregistering netfilter hooks
> [ 20.372051] type=1404 audit(1253208317.372:2): selinux=0 auid=4294967295 ses=4294967295
Same thing as your last report. I have a fix, but I can't seem to test
it because of the bug report I sent you last night. Chicken? Egg?
(you can work around with selinux=0)
-Eric
* Eric Paris <[email protected]> wrote:
> On Thu, 2009-09-17 at 17:19 +0200, Ingo Molnar wrote:
> > here's a new failure mode i havent seen before (possibly a variation of
> > the others):
> >
> > [ 20.036058] Freeing unused kernel memory: 1332k freed
> > [ 20.316099] SELinux: Disabled at runtime.
> > [ 20.320059] =============================================================================
> > [ 20.324029] BUG avc_node: Objects remaining on kmem_cache_close()
> > [ 20.324029] -----------------------------------------------------------------------------
> > [ 20.324029]
> > [ 20.324029] INFO: Slab 0xffffea0000de4230 objects=30 used=9 fp=0xffff88003f80a4c8 flags=0x4000000000000082
> > [ 20.324029] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> > [ 20.324029] Call Trace:
> > [ 20.324029] [<ffffffff810de4ba>] slab_err+0xb0/0xd2
> > [ 20.324029] [<ffffffff810dfa58>] list_slab_objects+0xa8/0x14e
> > [ 20.324029] [<ffffffff810e2d48>] kmem_cache_destroy+0x108/0x1d8
> > [ 20.324029] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> > [ 20.324029] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> > [ 20.324029] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> > [ 20.324029] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> > [ 20.324029] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> > [ 20.324029] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> > [ 20.324029] INFO: Object 0xffff88003f80a000 @offset=0
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5072 cpu=0 pid=0
> > [ 20.324029] INFO: Object 0xffff88003f80a088 @offset=136
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5055 cpu=0 pid=0
> > [ 20.324029] INFO: Object 0xffff88003f80a110 @offset=272
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4981 cpu=0 pid=6
> > [ 20.324029] INFO: Object 0xffff88003f80a198 @offset=408
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4229 cpu=0 pid=1
> > [ 20.324029] INFO: Object 0xffff88003f80a220 @offset=544
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> > [ 20.324029] INFO: Object 0xffff88003f80a2a8 @offset=680
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> > [ 20.324029] INFO: Object 0xffff88003f80a330 @offset=816
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=89 cpu=0 pid=1
> > [ 20.324029] INFO: Object 0xffff88003f80a3b8 @offset=952
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=57 cpu=0 pid=1
> > [ 20.324029] INFO: Object 0xffff88003f80a440 @offset=1088
> > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=48 cpu=0 pid=1
> > [ 20.324031] SLUB avc_node: kmem_cache_destroy called for cache that still has objects.
> > [ 20.328031] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> > [ 20.332031] Call Trace:
> > [ 20.334489] [<ffffffff810e2db7>] kmem_cache_destroy+0x177/0x1d8
> > [ 20.336032] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> > [ 20.340033] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> > [ 20.344032] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> > [ 20.348032] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> > [ 20.352032] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> > [ 20.356033] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> > [ 20.368209] SELinux: Unregistering netfilter hooks
> > [ 20.372051] type=1404 audit(1253208317.372:2): selinux=0 auid=4294967295 ses=4294967295
>
> Same thing as your last report. I have a fix, but I can't seem to
> test it because of the bug report I sent you last night. Chicken?
> Egg? (you can work around with selinux=0)
ah - got quite some backlog.
You said there:
Bisect comes down to: 774a694f8cd08115d130a290d73c6d8563f26b1b
commit 774a694f8cd08115d130a290d73c6d8563f26b1b
Merge: 4f0ac85... e1f8450...
Could you please double check the bisection result again, i.e. that all
of these are true:
774a694: bad
4f0ac85: good
e1f8450: good
?
But ... i'm not aware of any recent scheduler bug causing even anything
close to such symtomps. OTOH, timing changes due to scheduler changes
might have tickled some (new?) KVM code. One guess would be to flip the
default of kernel/sched_features.h: FAIR_SLEEPERS, or to flip the value
of kernel/sched_fair.c: sysctl_sched_child_runs_first from 0 to 1. Does
that make any difference to the symptoms?
Ingo
On Thu, 2009-09-17 at 18:21 +0200, Ingo Molnar wrote:
> * Eric Paris <[email protected]> wrote:
>
> > On Thu, 2009-09-17 at 17:19 +0200, Ingo Molnar wrote:
> > > here's a new failure mode i havent seen before (possibly a variation of
> > > the others):
> > >
> > > [ 20.036058] Freeing unused kernel memory: 1332k freed
> > > [ 20.316099] SELinux: Disabled at runtime.
> > > [ 20.320059] =============================================================================
> > > [ 20.324029] BUG avc_node: Objects remaining on kmem_cache_close()
> > > [ 20.324029] -----------------------------------------------------------------------------
> > > [ 20.324029]
> > > [ 20.324029] INFO: Slab 0xffffea0000de4230 objects=30 used=9 fp=0xffff88003f80a4c8 flags=0x4000000000000082
> > > [ 20.324029] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> > > [ 20.324029] Call Trace:
> > > [ 20.324029] [<ffffffff810de4ba>] slab_err+0xb0/0xd2
> > > [ 20.324029] [<ffffffff810dfa58>] list_slab_objects+0xa8/0x14e
> > > [ 20.324029] [<ffffffff810e2d48>] kmem_cache_destroy+0x108/0x1d8
> > > [ 20.324029] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> > > [ 20.324029] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> > > [ 20.324029] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> > > [ 20.324029] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> > > [ 20.324029] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> > > [ 20.324029] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> > > [ 20.324029] INFO: Object 0xffff88003f80a000 @offset=0
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5072 cpu=0 pid=0
> > > [ 20.324029] INFO: Object 0xffff88003f80a088 @offset=136
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=5055 cpu=0 pid=0
> > > [ 20.324029] INFO: Object 0xffff88003f80a110 @offset=272
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4981 cpu=0 pid=6
> > > [ 20.324029] INFO: Object 0xffff88003f80a198 @offset=408
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4229 cpu=0 pid=1
> > > [ 20.324029] INFO: Object 0xffff88003f80a220 @offset=544
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> > > [ 20.324029] INFO: Object 0xffff88003f80a2a8 @offset=680
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=4215 cpu=0 pid=1
> > > [ 20.324029] INFO: Object 0xffff88003f80a330 @offset=816
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=89 cpu=0 pid=1
> > > [ 20.324029] INFO: Object 0xffff88003f80a3b8 @offset=952
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=57 cpu=0 pid=1
> > > [ 20.324029] INFO: Object 0xffff88003f80a440 @offset=1088
> > > [ 20.324029] INFO: Allocated in avc_alloc_node+0x36/0x195 age=48 cpu=0 pid=1
> > > [ 20.324031] SLUB avc_node: kmem_cache_destroy called for cache that still has objects.
> > > [ 20.328031] Pid: 1, comm: init Not tainted 2.6.31-tip-06326-g7ed9b83-dirty #14930
> > > [ 20.332031] Call Trace:
> > > [ 20.334489] [<ffffffff810e2db7>] kmem_cache_destroy+0x177/0x1d8
> > > [ 20.336032] [<ffffffff813c3e44>] avc_disable+0x37/0x4d
> > > [ 20.340033] [<ffffffff813ccf39>] selinux_disable+0x53/0xb5
> > > [ 20.344032] [<ffffffff813cd692>] sel_write_disable+0xa2/0x110
> > > [ 20.348032] [<ffffffff810e68c7>] vfs_write+0xc2/0x132
> > > [ 20.352032] [<ffffffff810e6a37>] sys_write+0x5b/0x98
> > > [ 20.356033] [<ffffffff810120af>] system_call_fastpath+0x16/0x1b
> > > [ 20.368209] SELinux: Unregistering netfilter hooks
> > > [ 20.372051] type=1404 audit(1253208317.372:2): selinux=0 auid=4294967295 ses=4294967295
> >
> > Same thing as your last report. I have a fix, but I can't seem to
> > test it because of the bug report I sent you last night. Chicken?
> > Egg? (you can work around with selinux=0)
>
> ah - got quite some backlog.
>
> You said there:
>
> Bisect comes down to: 774a694f8cd08115d130a290d73c6d8563f26b1b
> commit 774a694f8cd08115d130a290d73c6d8563f26b1b
> Merge: 4f0ac85... e1f8450...
>
> Could you please double check the bisection result again, i.e. that all
> of these are true:
Sorry to be so slow to respond.
> 774a694: bad
Correct
> 4f0ac85: good
Correct.
> e1f8450: good
Incorrect
Just a couple more cycles to get a better commit. Not sure why the last
one stopped where it did.
-Eric