linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Re: Fw: Badness around put_cred()
       [not found] ` <20120126162820.GA7083@sergelap>
@ 2012-01-26 23:18   ` Robert Święcki
  2012-01-26 23:31     ` Paul E. McKenney
  2012-01-27 18:13   ` David Howells
  2012-01-27 18:25   ` David Howells
  2 siblings, 1 reply; 4+ messages in thread
From: Robert Święcki @ 2012-01-26 23:18 UTC (permalink / raw)
  To: Serge Hallyn; +Cc: Andrew Morton, Paul E. McKenney, David Howells, linux-kernel

On Thu, Jan 26, 2012 at 5:28 PM, Serge Hallyn
<serge.hallyn@canonical.com> wrote:
> Thanks, Andrew, I missed this in the list.  cc:ing David as he seems
> the most likely to know offhand what's going on.
>
> Robert, (please feel free to add lkml back to cc:) can you tell any
> more about exactly what/how you were fuzzing?

I'm fuzzing with http://code.google.com/p/iknowthis/ - it's a general
syscall fuzzer.

So, the problerm is that the counter reaches -1 in the cred structure.
I added code there (in put_cred()) which BUG_ON in the following code.

312	static inline void put_cred(const struct cred *_cred)
313	{
314		struct cred *cred = (struct cred *) _cred;
315	
316	        int r = atomic_dec_if_positive(&(cred)->usage);
...
...           my_code_for_stack_dumping
...
342	        BUG_ON(r == -1);
343	
344		if (r == 0)
345			__put_cred(cred);
346	}

I also added a code which registers stacktrace every counter
increas/decrease. I reserved 127 slots there (for PUT/GET) to find out
why number of get_cred()'s doesn't match number of put_cred()'s and
when it crashes all those slots are used, I must add them to find out
what's going on really. All in all, the stack dump is here:

http://alt.swiecki.net/linux_kernel/stacktrace_3.2-cred.txt

under GET there are stacktraces of all places where the cred counter
is increased, in PUT all places where it decreased. Unfortunately all
slots (128) are used, so it's not a full dump (just first 127 counter
increases/decreases).

Short kgdb session:
(gdb) target remote /dev/ttyS0
Remote debugging using /dev/ttyS0
put_cred (_cred=0xffff880054bb2180) at include/linux/cred.h:342
342	        BUG_ON(r == -1);

(gdb) bt
#0  put_cred (_cred=0xffff880054bb2180) at include/linux/cred.h:342
#1  0xffffffff810c31c6 in exit_creds (tsk=0xffff88006b8ca700) at
kernel/cred.c:199
#2  0xffffffff8109dad6 in __put_task_struct (tsk=0xffff88006b8ca700)
at kernel/fork.c:192
#3  0xffffffff810a0214 in put_task_struct (t=0x286) at
include/linux/sched.h:1753
#4  0xffffffff810a245d in delayed_put_task_struct (rhp=<optimized
out>) at kernel/exit.c:162
#5  0xffffffff810ffca6 in __rcu_reclaim (rn=<optimized out>,
head=<optimized out>) at kernel/rcu.h:81
#6  rcu_do_batch (rdp=<optimized out>, rsp=<optimized out>) at
kernel/rcutree.c:1292
#7  invoke_rcu_callbacks (rdp=<optimized out>, rsp=<optimized out>) at
kernel/rcutree.c:1577
#8  __rcu_process_callbacks (rsp=0xffffffff82c3c500,
rdp=0xffff88012bc4e960) at kernel/rcutree.c:1549
#9  0xffffffff810ffe89 in rcu_process_callbacks (unused=<optimized
out>) at kernel/rcutree.c:1558
#10 0xffffffff810a4624 in __do_softirq () at kernel/softirq.c:238
#11 0xffffffff8206283c in ?? () at arch/x86/kernel/entry_64.S:1205
#12 0xffffffff8104c2e3 in do_softirq () at arch/x86/kernel/irq_64.c:83
#13 0xffffffff810a42f8 in invoke_softirq () at kernel/softirq.c:329
#14 irq_exit () at kernel/softirq.c:348
#15 0xffffffff820631ef in smp_apic_timer_interrupt (regs=<optimized
out>) at arch/x86/kernel/apic/apic.c:882
#16 0xffffffff820610b3 in ?? () at arch/x86/kernel/entry_64.S:973


(gdb) p *(struct cred*)$rbx
$6 = {usage = {counter = 0}, uid = 1003, gid = 1003, suid = 1003, sgid
= 1003, euid = 1003, egid = 1003, fsuid = 1003, fsgid = 1003,
securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted = {cap
= {0, 0}}, cap_effective = {cap = {0, 0}}, cap_bset = {cap =
{4294967295,
      4294967295}}, jit_keyring = 0 '\000', thread_keyring = 0x0,
request_key_auth = 0x0, tgcred = 0xffff88004333e940, security =
0xffffffff83164a10, user = 0xffff8801214aa140, user_ns =
0xffffffff82c262f0, group_info = 0xffff8801097355c0, rcu = {next =
0x0,
    func = 0xffffffff810c3590 <put_cred_rcu>}

The counter is 0, cause I used
atomic_dec_if_positive(&(cred)->usage); - after that it would be -1.

[1]kdb> summary
sysname    Linux
release    3.2.0
version    #10 SMP Wed Jan 25 15:15:41 CET 2012
machine    x86_64
nodename   ise-test
domainname (none)
ccversion  CCVERSION
date       2012-01-26 22:51:34 tz_minuteswest -60
uptime     1 day 07:41
load avg   0.65 0.22 0.14

MemTotal:         992228 kB
MemFree:          652233 kB
Buffers:           34076 kB


I'll increase the number of slots for stack saving in the cred
structure, and will try to repeat it tomorrow.

> thanks,
> -serge
>
> Quoting Andrew Morton (akpm@linux-foundation.org):
>>
>> your code broke ;)
>>
>>
>> Begin forwarded message:
>>
>> Date: Tue, 17 Jan 2012 16:55:41 +0100
>> From: Robert Święcki <robert@swiecki.net>
>> To: linux-kernel@vger.kernel.org
>> Subject: Badness around put_cred()
>>
>>
>> Hi,
>>
>> I was fuzzing linux kernel for some time, and there seems to be a bug,
>> which kicks in relatively quickly (a few hours at most), which ends up
>> with warn() or panic() - depending on options compiled in
>> (CONFIG_DEBUG_CREDENTIALS, preemption mode). I was looking briefly
>> through kernel code, and I think it might be related to the
>> include/linux/cred.h::
>>
>> static inline void put_cred(const struct cred *_cred)
>> {
>>         struct cred *cred = (struct cred *) _cred;
>>
>>         validate_creds(cred);
>>         if (atomic_dec_and_test(&(cred)->usage))
>>                 __put_cred(cred);
>> }
>>
>> which checks whether the usage counter is different than 0, and maybe
>> it should be checking whether it is >0.
>>
>> All in all, I don't understand the whole cred/rcu code yet, so just
>> dumping the data, in case somebody else can spot the problem quicker.
>> The kernel versions are 2.6.39 and 3.2
>>
>> Config: CONFIG_DEBUG_CREDENTIALS=n, CONFIG_PREEMPT_RCU=n,
>> CONFIG_PREEMPT=n, kernel=3.2
>>
>> (gdb) bt
>> #0  kgdb_breakpoint () at kernel/debug/debug_core.c:960
>> #1  kgdb_panic_event (self=0x286, val=0, data=0x0) at
>> kernel/debug/debug_core.c:766
>> #2  0xffffffff810c1eff in notifier_call_chain (nl=<optimized out>,
>> val=0, v=0xffffffff8301a9b0, nr_to_call=-1, nr_calls=<optimized out>)
>> at kernel/notifier.c:93
>> #3  0xffffffff810c1f57 in __atomic_notifier_call_chain
>> (nr_calls=<optimized out>, nr_to_call=<optimized out>, v=<optimized
>> out>, val=<optimized out>, nh=<optimized out>) at
>> kernel/notifier.c:190
>> #4  atomic_notifier_call_chain (nh=<optimized out>, val=0, v=0x0) at
>> kernel/notifier.c:191
>> #5  0xffffffff8205abc5 in panic (fmt=0xffffffff829c20f5 "CRED:
>> put_cred_rcu() sees %p with usage %d\n") at kernel/panic.c:100
>> #6  0xffffffff810c3365 in put_cred_rcu (rcu=0xffff880118552b88) at
>> kernel/cred.c:139
>> #7  0xffffffff810ffa52 in __rcu_reclaim (rn=<optimized out>,
>> head=<optimized out>) at kernel/rcu.h:81
>> #8  rcu_do_batch (rdp=<optimized out>, rsp=<optimized out>) at
>> kernel/rcutree.c:1292
>> #9  invoke_rcu_callbacks (rdp=<optimized out>, rsp=<optimized out>) at
>> kernel/rcutree.c:1577
>> #10 __rcu_process_callbacks (rsp=0xffffffff82c34500,
>> rdp=0xffff88012bc4e960) at kernel/rcutree.c:1549
>> #11 0xffffffff810ffc35 in rcu_process_callbacks (unused=<optimized
>> out>) at kernel/rcutree.c:1558
>> #12 0xffffffff810a4630 in __do_softirq () at kernel/softirq.c:238
>> #13 0xffffffff820602fc in ?? () at arch/x86/kernel/entry_64.S:1205
>> #14 0xffffffff8104c2e3 in do_softirq () at arch/x86/kernel/irq_64.c:83
>> #15 0xffffffff810a4304 in invoke_softirq () at kernel/softirq.c:329
>> #16 irq_exit () at kernel/softirq.c:348
>> #17 0xffffffff82060caf in smp_apic_timer_interrupt (regs=<optimized
>> out>) at arch/x86/kernel/apic/apic.c:882
>> #18 0xffffffff8205eb73 in ?? () at arch/x86/kernel/entry_64.S:973
>> Backtrace stopped: previous frame inner to this frame (corrupt stack?)
>> (gdb) up
>> #1  kgdb_panic_event (self=0x286, val=0, data=0x0) at
>> kernel/debug/debug_core.c:766
>> 766           kgdb_breakpoint();
>> (gdb) up
>> #2  0xffffffff810c1eff in notifier_call_chain (nl=<optimized out>,
>> val=0, v=0xffffffff8301a9b0, nr_to_call=-1, nr_calls=<optimized out>)
>> at kernel/notifier.c:93
>> 93                    ret = nb->notifier_call(nb, val, v);
>> (gdb) up
>> #3  0xffffffff810c1f57 in __atomic_notifier_call_chain
>> (nr_calls=<optimized out>, nr_to_call=<optimized out>, v=<optimized
>> out>, val=<optimized out>, nh=<optimized out>) at
>> kernel/notifier.c:190
>> 190   {
>> (gdb) up
>> #4  atomic_notifier_call_chain (nh=<optimized out>, val=0, v=0x0) at
>> kernel/notifier.c:191
>> 191           return __atomic_notifier_call_chain(nh, val, v, -1, NULL);
>> (gdb)
>> #5  0xffffffff8205abc5 in panic (fmt=0xffffffff829c20f5 "CRED:
>> put_cred_rcu() sees %p with usage %d\n") at kernel/panic.c:100
>> 100           atomic_notifier_call_chain(&panic_notifier_list, 0, buf);
>> (gdb)
>> #6  0xffffffff810c3365 in put_cred_rcu (rcu=0xffff880118552b88) at
>> kernel/cred.c:139
>> 139                   panic("CRED: put_cred_rcu() sees %p with usage %d\n",
>> (gdb) list
>> 134                         cred, cred->magic, cred->put_addr,
>> 135                         atomic_read(&cred->usage),
>> 136                         read_cred_subscribers(cred));
>> 137   #else
>> 138           if (atomic_read(&cred->usage) != 0)
>> 139                   panic("CRED: put_cred_rcu() sees %p with usage %d\n",
>> 140                         cred, atomic_read(&cred->usage));
>> 141   #endif
>> 142
>> 143           security_cred_free(cred);
>> (gdb) p cred
>> $1 = (struct cred *) 0xffff880118552b00
>> (gdb) p *cred
>> $2 = {usage = {counter = -1}, uid = 1001, gid = 1001, suid = 1001,
>> sgid = 1001, euid = 1001, egid = 1001, fsuid = 1001, fsgid = 1001,
>> securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted = {cap
>> = {0, 0}}, cap_effective = {
>>     cap = {0, 0}}, cap_bset = {cap = {4294967295, 4294967295}},
>> jit_keyring = 0 '\000', thread_keyring = 0x0, request_key_auth = 0x0,
>> tgcred = 0xffff880116a3ed80, security = 0xffffffff8315ca10, user =
>> 0xffff880122242a40,
>>   user_ns = 0xffffffff82c262f0, group_info = 0xffff88011a5d9240, rcu =
>> {next = 0xffff880111a4e348, func = 0xffffffff810c332e <put_cred_rcu>}}
>>
>>
>>
>>
>>
>>
>>
>> Config: CONFIG_DEBUG_CREDENTIALS=y, CONFIG_PREEMPT_RCU=y,
>> CONFIG_PREEMPT=y, kernel=2.6.39
>>
>> =====================================================================
>> KDB
>> =====================================================================
>>
>> <3>[49754.391126] CRED: Invalid credentials
>> <3>[49754.394811] CRED: At include/linux/cred.h:260
>> <3>[49754.399181] CRED: Specified credentials: ffff8801156c8b00
>> <3>[49754.404676] CRED: ->magic=44656144, put_addr=ffffffff81166dc5
>> <3>[49754.410430] CRED: ->usage=0, subscr=0
>> <3>[49754.414102] CRED: ->*uid = { 65534,65534,65534,65534 }
>> <3>[49754.419250] CRED: ->*gid = { 65534,65534,65534,65534 }
>> <3>[49754.424397] CRED: ->security is ffff8801113069c0
>> <3>[49754.429021] CRED: ->security {1, 1}
>>
>> [1]kdb> bt
>> Stack traceback for pid 16009
>> 0xffff880115819770    16009     8897  1    1   R  0xffff880115819bf0 *iknowthis2
>> <c> ffff88012bc43e00<c> 0000000000000000<c> ffff880100000104<c>
>> ffffffff8267436f<c>
>> <c> ffffffff81b611cd<c> ffff8801156c8b00<c> ffff88012bc43e40<c>
>> ffffffff81166d8e<c>
>> <c> ffff8801156c8b00<c> ffff880121e13540<c> ffff88012bc43e60<c>
>> ffffffff81166db3<c>
>> Call Trace:
>>  <IRQ>  [<ffffffff81b611cd>] ? wq_free_rcu+0x12/0x14
>>  [<ffffffff81166d8e>] ? __validate_creds.clone.9+0x2d/0x32
>>  [<ffffffff81166db3>] ? file_free_rcu+0x20/0x46
>>  [<ffffffff810eeb82>] ? __rcu_process_callbacks+0x18d/0x2af
>>  [<ffffffff810eed24>] ? rcu_process_callbacks+0x80/0x87
>>  [<ffffffff8109c013>] ? __do_softirq+0xeb/0x1cc
>>  [<ffffffff81044977>] ? native_sched_clock+0x35/0x37
>>  [<ffffffff810b67dd>] ? sched_clock_local+0x12/0x75
>>  [<ffffffff81edbd9c>] ? call_softirq+0x1c/0x30
>>  [<ffffffff81040510>] ? do_softirq+0x4b/0x9f
>>  [<ffffffff8109c380>] ? irq_exit+0x5f/0xb6
>>  [<ffffffff81edc6d1>] ? smp_apic_timer_interrupt+0x7d/0x8b
>>  [<ffffffff81edb553>] ? apic_timer_interrupt+0x13/0x20
>>  <EOI>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
>>  [<ffffffff81151cdb>] ? arch_local_irq_restore+0x6/0xd
>>  [<ffffffff81154ceb>] ? __slab_alloc.clone.36+0xf0/0x38b
>>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
>>  [<ffffffff81155143>] ? kmem_cache_alloc+0x4a/0xe7
>>  [<ffffffff8135b0ce>] ? selinux_vm_enough_memory+0x48/0x4d
>>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
>>  [<ffffffff81094c56>] ? copy_process+0xa3e/0x1230
>>  [<ffffffff81095592>] ? do_fork+0x10f/0x29d
>>  [<ffffffff813d8dba>] ? trace_hardirqs_off_thunk+0x3a/0x6c
>>  [<ffffffff8107e5b9>] ? sys32_clone+0x26/0x28
>>  [<ffffffff81edc585>] ? ia32_ptregs_common+0x25/0x4b
>>
>> [dumpcommon]kdb>   -summary
>>
>> sysname    Linux
>> release    2.6.39
>> version    #3 SMP PREEMPT Fri May 27 15:27:03 CEST 2011
>> machine    x86_64
>> nodename   ise-test
>> domainname (none)
>> ccversion  CCVERSION
>> date       2011-05-28 03:20:03 tz_minuteswest -120
>> uptime     13:49
>> load avg   19.38 20.17 22.96
>>
>> MemTotal:         993059 kB
>> MemFree:          458493 kB
>> Buffers:           23981 kB
>>
>>
>> =====================================================================
>> KGDB
>> =====================================================================
>>
>> (gdb) bt
>> #0  __invalid_creds (cred=0xffff8801156c8b00, file=<value optimized
>> out>, line=<value optimized out>)
>>     at kernel/cred.c:812
>> #1  0xffffffff81166d8e in __validate_creds (cred=0xffff8801156c8b00, line=260,
>>     file=0xffffffff8267436f "include/linux/cred.h") at include/linux/cred.h:186
>> #2  0xffffffff81166db3 in put_cred (head=<value optimized out>) at
>> include/linux/cred.h:260
>> #3  file_free_rcu (head=<value optimized out>) at fs/file_table.c:49
>> #4  0xffffffff810eeb82 in rcu_do_batch (rsp=0xffffffff82a2f500,
>> rdp=0xffff88012bc502f0) at kernel/rcutree.c:1146
>> #5  __rcu_process_callbacks (rsp=0xffffffff82a2f500,
>> rdp=0xffff88012bc502f0) at kernel/rcutree.c:1386
>> #6  0xffffffff810eed24 in rcu_preempt_process_callbacks (unused=<value
>> optimized out>) at kernel/rcutree_plugin.h:544
>> #7  rcu_process_callbacks (unused=<value optimized out>) at
>> kernel/rcutree.c:1404
>> #8  0xffffffff8109c013 in __do_softirq () at kernel/softirq.c:238
>> #9  0xffffffff81edbd9c in ?? () at arch/x86/kernel/entry_64.S:1210
>> #10 0xffffffff81040510 in do_softirq () at arch/x86/kernel/irq_64.c:80
>> #11 0xffffffff8109c380 in invoke_softirq () at kernel/softirq.c:325
>> #12 irq_exit () at kernel/softirq.c:340
>> #13 0xffffffff81edc6d1 in smp_apic_timer_interrupt (regs=<value
>> optimized out>) at arch/x86/kernel/apic/apic.c:861
>> #14 <signal handler called>
>> #15 0x00cf9b000000ffff in __brk_reservation_fn_dmi_alloc__ ()
>> Cannot access memory at address 0xcffb000000ffff
>>
>> Cannot access memory at address 0xcffb000000ffff
>> (gdb) up
>> #1  0xffffffff81166d8e in __validate_creds (cred=0xffff8801156c8b00, line=260,
>>     file=0xffffffff8267436f "include/linux/cred.h") at include/linux/cred.h:186
>> 186                   __invalid_creds(cred, file, line);
>> (gdb) p *cred
>> $1 = {usage = {counter = 0}, subscribers = {counter = 0}, put_addr =
>> 0xffffffff81166dc5, magic = 1147494724,
>>   uid = 65534, gid = 65534, suid = 65534, sgid = 65534, euid = 65534,
>> egid = 65534, fsuid = 65534, fsgid = 65534,
>>   securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted =
>> {cap = {0, 0}}, cap_effective = {cap = {0, 0}},
>>   cap_bset = {cap = {4294967295, 4294967295}}, jit_keyring = 0 '\000',
>> thread_keyring = 0x0, request_key_auth = 0x0,
>>   tgcred = 0xffff88011492b088, security = 0xffff8801113069c0, user =
>> 0xffff880121c4b000, user_ns = 0xffffffff82a21a80,
>>   group_info = 0xffff880104cec420, rcu = {next = 0x0, func =
>> 0xffffffff810b6c97 <put_cred_rcu>}}
>>
>> (gdb) p (char[4])cred->magic
>> $8 = "DaeD"
>>
>>
>>
>> --
>> Robert Święcki
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>> Please read the FAQ at  http://www.tux.org/lkml/



-- 
Robert Święcki

^ permalink raw reply	[flat|nested] 4+ messages in thread
* Re: Fw: Badness around put_cred()
  2012-01-26 23:18   ` Fw: Badness around put_cred() Robert Święcki
@ 2012-01-26 23:31     ` Paul E. McKenney
  0 siblings, 0 replies; 4+ messages in thread
From: Paul E. McKenney @ 2012-01-26 23:31 UTC (permalink / raw)
  To: Robert Święcki
  Cc: Serge Hallyn, Andrew Morton, David Howells, linux-kernel

On Fri, Jan 27, 2012 at 12:18:09AM +0100, Robert Święcki wrote:
> On Thu, Jan 26, 2012 at 5:28 PM, Serge Hallyn
> <serge.hallyn@canonical.com> wrote:
> > Thanks, Andrew, I missed this in the list.  cc:ing David as he seems
> > the most likely to know offhand what's going on.
> >
> > Robert, (please feel free to add lkml back to cc:) can you tell any
> > more about exactly what/how you were fuzzing?
> 
> I'm fuzzing with http://code.google.com/p/iknowthis/ - it's a general
> syscall fuzzer.

Can you record the system calls that the fuzzer is doing to get to
this point, perhaps using strace?  If you can isolate a short sequence
of system calls that makes the problem happen, that would be even
better.

							Thanx, Paul

> So, the problerm is that the counter reaches -1 in the cred structure.
> I added code there (in put_cred()) which BUG_ON in the following code.
> 
> 312	static inline void put_cred(const struct cred *_cred)
> 313	{
> 314		struct cred *cred = (struct cred *) _cred;
> 315	
> 316	        int r = atomic_dec_if_positive(&(cred)->usage);
> ...
> ...           my_code_for_stack_dumping
> ...
> 342	        BUG_ON(r == -1);
> 343	
> 344		if (r == 0)
> 345			__put_cred(cred);
> 346	}
> 
> I also added a code which registers stacktrace every counter
> increas/decrease. I reserved 127 slots there (for PUT/GET) to find out
> why number of get_cred()'s doesn't match number of put_cred()'s and
> when it crashes all those slots are used, I must add them to find out
> what's going on really. All in all, the stack dump is here:
> 
> http://alt.swiecki.net/linux_kernel/stacktrace_3.2-cred.txt
> 
> under GET there are stacktraces of all places where the cred counter
> is increased, in PUT all places where it decreased. Unfortunately all
> slots (128) are used, so it's not a full dump (just first 127 counter
> increases/decreases).
> 
> Short kgdb session:
> (gdb) target remote /dev/ttyS0
> Remote debugging using /dev/ttyS0
> put_cred (_cred=0xffff880054bb2180) at include/linux/cred.h:342
> 342	        BUG_ON(r == -1);
> 
> (gdb) bt
> #0  put_cred (_cred=0xffff880054bb2180) at include/linux/cred.h:342
> #1  0xffffffff810c31c6 in exit_creds (tsk=0xffff88006b8ca700) at
> kernel/cred.c:199
> #2  0xffffffff8109dad6 in __put_task_struct (tsk=0xffff88006b8ca700)
> at kernel/fork.c:192
> #3  0xffffffff810a0214 in put_task_struct (t=0x286) at
> include/linux/sched.h:1753
> #4  0xffffffff810a245d in delayed_put_task_struct (rhp=<optimized
> out>) at kernel/exit.c:162
> #5  0xffffffff810ffca6 in __rcu_reclaim (rn=<optimized out>,
> head=<optimized out>) at kernel/rcu.h:81
> #6  rcu_do_batch (rdp=<optimized out>, rsp=<optimized out>) at
> kernel/rcutree.c:1292
> #7  invoke_rcu_callbacks (rdp=<optimized out>, rsp=<optimized out>) at
> kernel/rcutree.c:1577
> #8  __rcu_process_callbacks (rsp=0xffffffff82c3c500,
> rdp=0xffff88012bc4e960) at kernel/rcutree.c:1549
> #9  0xffffffff810ffe89 in rcu_process_callbacks (unused=<optimized
> out>) at kernel/rcutree.c:1558
> #10 0xffffffff810a4624 in __do_softirq () at kernel/softirq.c:238
> #11 0xffffffff8206283c in ?? () at arch/x86/kernel/entry_64.S:1205
> #12 0xffffffff8104c2e3 in do_softirq () at arch/x86/kernel/irq_64.c:83
> #13 0xffffffff810a42f8 in invoke_softirq () at kernel/softirq.c:329
> #14 irq_exit () at kernel/softirq.c:348
> #15 0xffffffff820631ef in smp_apic_timer_interrupt (regs=<optimized
> out>) at arch/x86/kernel/apic/apic.c:882
> #16 0xffffffff820610b3 in ?? () at arch/x86/kernel/entry_64.S:973
> 
> 
> (gdb) p *(struct cred*)$rbx
> $6 = {usage = {counter = 0}, uid = 1003, gid = 1003, suid = 1003, sgid
> = 1003, euid = 1003, egid = 1003, fsuid = 1003, fsgid = 1003,
> securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted = {cap
> = {0, 0}}, cap_effective = {cap = {0, 0}}, cap_bset = {cap =
> {4294967295,
>       4294967295}}, jit_keyring = 0 '\000', thread_keyring = 0x0,
> request_key_auth = 0x0, tgcred = 0xffff88004333e940, security =
> 0xffffffff83164a10, user = 0xffff8801214aa140, user_ns =
> 0xffffffff82c262f0, group_info = 0xffff8801097355c0, rcu = {next =
> 0x0,
>     func = 0xffffffff810c3590 <put_cred_rcu>}
> 
> The counter is 0, cause I used
> atomic_dec_if_positive(&(cred)->usage); - after that it would be -1.
> 
> [1]kdb> summary
> sysname    Linux
> release    3.2.0
> version    #10 SMP Wed Jan 25 15:15:41 CET 2012
> machine    x86_64
> nodename   ise-test
> domainname (none)
> ccversion  CCVERSION
> date       2012-01-26 22:51:34 tz_minuteswest -60
> uptime     1 day 07:41
> load avg   0.65 0.22 0.14
> 
> MemTotal:         992228 kB
> MemFree:          652233 kB
> Buffers:           34076 kB
> 
> 
> I'll increase the number of slots for stack saving in the cred
> structure, and will try to repeat it tomorrow.
> 
> > thanks,
> > -serge
> >
> > Quoting Andrew Morton (akpm@linux-foundation.org):
> >>
> >> your code broke ;)
> >>
> >>
> >> Begin forwarded message:
> >>
> >> Date: Tue, 17 Jan 2012 16:55:41 +0100
> >> From: Robert Święcki <robert@swiecki.net>
> >> To: linux-kernel@vger.kernel.org
> >> Subject: Badness around put_cred()
> >>
> >>
> >> Hi,
> >>
> >> I was fuzzing linux kernel for some time, and there seems to be a bug,
> >> which kicks in relatively quickly (a few hours at most), which ends up
> >> with warn() or panic() - depending on options compiled in
> >> (CONFIG_DEBUG_CREDENTIALS, preemption mode). I was looking briefly
> >> through kernel code, and I think it might be related to the
> >> include/linux/cred.h::
> >>
> >> static inline void put_cred(const struct cred *_cred)
> >> {
> >>         struct cred *cred = (struct cred *) _cred;
> >>
> >>         validate_creds(cred);
> >>         if (atomic_dec_and_test(&(cred)->usage))
> >>                 __put_cred(cred);
> >> }
> >>
> >> which checks whether the usage counter is different than 0, and maybe
> >> it should be checking whether it is >0.
> >>
> >> All in all, I don't understand the whole cred/rcu code yet, so just
> >> dumping the data, in case somebody else can spot the problem quicker.
> >> The kernel versions are 2.6.39 and 3.2
> >>
> >> Config: CONFIG_DEBUG_CREDENTIALS=n, CONFIG_PREEMPT_RCU=n,
> >> CONFIG_PREEMPT=n, kernel=3.2
> >>
> >> (gdb) bt
> >> #0  kgdb_breakpoint () at kernel/debug/debug_core.c:960
> >> #1  kgdb_panic_event (self=0x286, val=0, data=0x0) at
> >> kernel/debug/debug_core.c:766
> >> #2  0xffffffff810c1eff in notifier_call_chain (nl=<optimized out>,
> >> val=0, v=0xffffffff8301a9b0, nr_to_call=-1, nr_calls=<optimized out>)
> >> at kernel/notifier.c:93
> >> #3  0xffffffff810c1f57 in __atomic_notifier_call_chain
> >> (nr_calls=<optimized out>, nr_to_call=<optimized out>, v=<optimized
> >> out>, val=<optimized out>, nh=<optimized out>) at
> >> kernel/notifier.c:190
> >> #4  atomic_notifier_call_chain (nh=<optimized out>, val=0, v=0x0) at
> >> kernel/notifier.c:191
> >> #5  0xffffffff8205abc5 in panic (fmt=0xffffffff829c20f5 "CRED:
> >> put_cred_rcu() sees %p with usage %d\n") at kernel/panic.c:100
> >> #6  0xffffffff810c3365 in put_cred_rcu (rcu=0xffff880118552b88) at
> >> kernel/cred.c:139
> >> #7  0xffffffff810ffa52 in __rcu_reclaim (rn=<optimized out>,
> >> head=<optimized out>) at kernel/rcu.h:81
> >> #8  rcu_do_batch (rdp=<optimized out>, rsp=<optimized out>) at
> >> kernel/rcutree.c:1292
> >> #9  invoke_rcu_callbacks (rdp=<optimized out>, rsp=<optimized out>) at
> >> kernel/rcutree.c:1577
> >> #10 __rcu_process_callbacks (rsp=0xffffffff82c34500,
> >> rdp=0xffff88012bc4e960) at kernel/rcutree.c:1549
> >> #11 0xffffffff810ffc35 in rcu_process_callbacks (unused=<optimized
> >> out>) at kernel/rcutree.c:1558
> >> #12 0xffffffff810a4630 in __do_softirq () at kernel/softirq.c:238
> >> #13 0xffffffff820602fc in ?? () at arch/x86/kernel/entry_64.S:1205
> >> #14 0xffffffff8104c2e3 in do_softirq () at arch/x86/kernel/irq_64.c:83
> >> #15 0xffffffff810a4304 in invoke_softirq () at kernel/softirq.c:329
> >> #16 irq_exit () at kernel/softirq.c:348
> >> #17 0xffffffff82060caf in smp_apic_timer_interrupt (regs=<optimized
> >> out>) at arch/x86/kernel/apic/apic.c:882
> >> #18 0xffffffff8205eb73 in ?? () at arch/x86/kernel/entry_64.S:973
> >> Backtrace stopped: previous frame inner to this frame (corrupt stack?)
> >> (gdb) up
> >> #1  kgdb_panic_event (self=0x286, val=0, data=0x0) at
> >> kernel/debug/debug_core.c:766
> >> 766           kgdb_breakpoint();
> >> (gdb) up
> >> #2  0xffffffff810c1eff in notifier_call_chain (nl=<optimized out>,
> >> val=0, v=0xffffffff8301a9b0, nr_to_call=-1, nr_calls=<optimized out>)
> >> at kernel/notifier.c:93
> >> 93                    ret = nb->notifier_call(nb, val, v);
> >> (gdb) up
> >> #3  0xffffffff810c1f57 in __atomic_notifier_call_chain
> >> (nr_calls=<optimized out>, nr_to_call=<optimized out>, v=<optimized
> >> out>, val=<optimized out>, nh=<optimized out>) at
> >> kernel/notifier.c:190
> >> 190   {
> >> (gdb) up
> >> #4  atomic_notifier_call_chain (nh=<optimized out>, val=0, v=0x0) at
> >> kernel/notifier.c:191
> >> 191           return __atomic_notifier_call_chain(nh, val, v, -1, NULL);
> >> (gdb)
> >> #5  0xffffffff8205abc5 in panic (fmt=0xffffffff829c20f5 "CRED:
> >> put_cred_rcu() sees %p with usage %d\n") at kernel/panic.c:100
> >> 100           atomic_notifier_call_chain(&panic_notifier_list, 0, buf);
> >> (gdb)
> >> #6  0xffffffff810c3365 in put_cred_rcu (rcu=0xffff880118552b88) at
> >> kernel/cred.c:139
> >> 139                   panic("CRED: put_cred_rcu() sees %p with usage %d\n",
> >> (gdb) list
> >> 134                         cred, cred->magic, cred->put_addr,
> >> 135                         atomic_read(&cred->usage),
> >> 136                         read_cred_subscribers(cred));
> >> 137   #else
> >> 138           if (atomic_read(&cred->usage) != 0)
> >> 139                   panic("CRED: put_cred_rcu() sees %p with usage %d\n",
> >> 140                         cred, atomic_read(&cred->usage));
> >> 141   #endif
> >> 142
> >> 143           security_cred_free(cred);
> >> (gdb) p cred
> >> $1 = (struct cred *) 0xffff880118552b00
> >> (gdb) p *cred
> >> $2 = {usage = {counter = -1}, uid = 1001, gid = 1001, suid = 1001,
> >> sgid = 1001, euid = 1001, egid = 1001, fsuid = 1001, fsgid = 1001,
> >> securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted = {cap
> >> = {0, 0}}, cap_effective = {
> >>     cap = {0, 0}}, cap_bset = {cap = {4294967295, 4294967295}},
> >> jit_keyring = 0 '\000', thread_keyring = 0x0, request_key_auth = 0x0,
> >> tgcred = 0xffff880116a3ed80, security = 0xffffffff8315ca10, user =
> >> 0xffff880122242a40,
> >>   user_ns = 0xffffffff82c262f0, group_info = 0xffff88011a5d9240, rcu =
> >> {next = 0xffff880111a4e348, func = 0xffffffff810c332e <put_cred_rcu>}}
> >>
> >>
> >>
> >>
> >>
> >>
> >>
> >> Config: CONFIG_DEBUG_CREDENTIALS=y, CONFIG_PREEMPT_RCU=y,
> >> CONFIG_PREEMPT=y, kernel=2.6.39
> >>
> >> =====================================================================
> >> KDB
> >> =====================================================================
> >>
> >> <3>[49754.391126] CRED: Invalid credentials
> >> <3>[49754.394811] CRED: At include/linux/cred.h:260
> >> <3>[49754.399181] CRED: Specified credentials: ffff8801156c8b00
> >> <3>[49754.404676] CRED: ->magic=44656144, put_addr=ffffffff81166dc5
> >> <3>[49754.410430] CRED: ->usage=0, subscr=0
> >> <3>[49754.414102] CRED: ->*uid = { 65534,65534,65534,65534 }
> >> <3>[49754.419250] CRED: ->*gid = { 65534,65534,65534,65534 }
> >> <3>[49754.424397] CRED: ->security is ffff8801113069c0
> >> <3>[49754.429021] CRED: ->security {1, 1}
> >>
> >> [1]kdb> bt
> >> Stack traceback for pid 16009
> >> 0xffff880115819770    16009     8897  1    1   R  0xffff880115819bf0 *iknowthis2
> >> <c> ffff88012bc43e00<c> 0000000000000000<c> ffff880100000104<c>
> >> ffffffff8267436f<c>
> >> <c> ffffffff81b611cd<c> ffff8801156c8b00<c> ffff88012bc43e40<c>
> >> ffffffff81166d8e<c>
> >> <c> ffff8801156c8b00<c> ffff880121e13540<c> ffff88012bc43e60<c>
> >> ffffffff81166db3<c>
> >> Call Trace:
> >>  <IRQ>  [<ffffffff81b611cd>] ? wq_free_rcu+0x12/0x14
> >>  [<ffffffff81166d8e>] ? __validate_creds.clone.9+0x2d/0x32
> >>  [<ffffffff81166db3>] ? file_free_rcu+0x20/0x46
> >>  [<ffffffff810eeb82>] ? __rcu_process_callbacks+0x18d/0x2af
> >>  [<ffffffff810eed24>] ? rcu_process_callbacks+0x80/0x87
> >>  [<ffffffff8109c013>] ? __do_softirq+0xeb/0x1cc
> >>  [<ffffffff81044977>] ? native_sched_clock+0x35/0x37
> >>  [<ffffffff810b67dd>] ? sched_clock_local+0x12/0x75
> >>  [<ffffffff81edbd9c>] ? call_softirq+0x1c/0x30
> >>  [<ffffffff81040510>] ? do_softirq+0x4b/0x9f
> >>  [<ffffffff8109c380>] ? irq_exit+0x5f/0xb6
> >>  [<ffffffff81edc6d1>] ? smp_apic_timer_interrupt+0x7d/0x8b
> >>  [<ffffffff81edb553>] ? apic_timer_interrupt+0x13/0x20
> >>  <EOI>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
> >>  [<ffffffff81151cdb>] ? arch_local_irq_restore+0x6/0xd
> >>  [<ffffffff81154ceb>] ? __slab_alloc.clone.36+0xf0/0x38b
> >>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
> >>  [<ffffffff81155143>] ? kmem_cache_alloc+0x4a/0xe7
> >>  [<ffffffff8135b0ce>] ? selinux_vm_enough_memory+0x48/0x4d
> >>  [<ffffffff81093f75>] ? dup_mm+0x1f2/0x468
> >>  [<ffffffff81094c56>] ? copy_process+0xa3e/0x1230
> >>  [<ffffffff81095592>] ? do_fork+0x10f/0x29d
> >>  [<ffffffff813d8dba>] ? trace_hardirqs_off_thunk+0x3a/0x6c
> >>  [<ffffffff8107e5b9>] ? sys32_clone+0x26/0x28
> >>  [<ffffffff81edc585>] ? ia32_ptregs_common+0x25/0x4b
> >>
> >> [dumpcommon]kdb>   -summary
> >>
> >> sysname    Linux
> >> release    2.6.39
> >> version    #3 SMP PREEMPT Fri May 27 15:27:03 CEST 2011
> >> machine    x86_64
> >> nodename   ise-test
> >> domainname (none)
> >> ccversion  CCVERSION
> >> date       2011-05-28 03:20:03 tz_minuteswest -120
> >> uptime     13:49
> >> load avg   19.38 20.17 22.96
> >>
> >> MemTotal:         993059 kB
> >> MemFree:          458493 kB
> >> Buffers:           23981 kB
> >>
> >>
> >> =====================================================================
> >> KGDB
> >> =====================================================================
> >>
> >> (gdb) bt
> >> #0  __invalid_creds (cred=0xffff8801156c8b00, file=<value optimized
> >> out>, line=<value optimized out>)
> >>     at kernel/cred.c:812
> >> #1  0xffffffff81166d8e in __validate_creds (cred=0xffff8801156c8b00, line=260,
> >>     file=0xffffffff8267436f "include/linux/cred.h") at include/linux/cred.h:186
> >> #2  0xffffffff81166db3 in put_cred (head=<value optimized out>) at
> >> include/linux/cred.h:260
> >> #3  file_free_rcu (head=<value optimized out>) at fs/file_table.c:49
> >> #4  0xffffffff810eeb82 in rcu_do_batch (rsp=0xffffffff82a2f500,
> >> rdp=0xffff88012bc502f0) at kernel/rcutree.c:1146
> >> #5  __rcu_process_callbacks (rsp=0xffffffff82a2f500,
> >> rdp=0xffff88012bc502f0) at kernel/rcutree.c:1386
> >> #6  0xffffffff810eed24 in rcu_preempt_process_callbacks (unused=<value
> >> optimized out>) at kernel/rcutree_plugin.h:544
> >> #7  rcu_process_callbacks (unused=<value optimized out>) at
> >> kernel/rcutree.c:1404
> >> #8  0xffffffff8109c013 in __do_softirq () at kernel/softirq.c:238
> >> #9  0xffffffff81edbd9c in ?? () at arch/x86/kernel/entry_64.S:1210
> >> #10 0xffffffff81040510 in do_softirq () at arch/x86/kernel/irq_64.c:80
> >> #11 0xffffffff8109c380 in invoke_softirq () at kernel/softirq.c:325
> >> #12 irq_exit () at kernel/softirq.c:340
> >> #13 0xffffffff81edc6d1 in smp_apic_timer_interrupt (regs=<value
> >> optimized out>) at arch/x86/kernel/apic/apic.c:861
> >> #14 <signal handler called>
> >> #15 0x00cf9b000000ffff in __brk_reservation_fn_dmi_alloc__ ()
> >> Cannot access memory at address 0xcffb000000ffff
> >>
> >> Cannot access memory at address 0xcffb000000ffff
> >> (gdb) up
> >> #1  0xffffffff81166d8e in __validate_creds (cred=0xffff8801156c8b00, line=260,
> >>     file=0xffffffff8267436f "include/linux/cred.h") at include/linux/cred.h:186
> >> 186                   __invalid_creds(cred, file, line);
> >> (gdb) p *cred
> >> $1 = {usage = {counter = 0}, subscribers = {counter = 0}, put_addr =
> >> 0xffffffff81166dc5, magic = 1147494724,
> >>   uid = 65534, gid = 65534, suid = 65534, sgid = 65534, euid = 65534,
> >> egid = 65534, fsuid = 65534, fsgid = 65534,
> >>   securebits = 0, cap_inheritable = {cap = {0, 0}}, cap_permitted =
> >> {cap = {0, 0}}, cap_effective = {cap = {0, 0}},
> >>   cap_bset = {cap = {4294967295, 4294967295}}, jit_keyring = 0 '\000',
> >> thread_keyring = 0x0, request_key_auth = 0x0,
> >>   tgcred = 0xffff88011492b088, security = 0xffff8801113069c0, user =
> >> 0xffff880121c4b000, user_ns = 0xffffffff82a21a80,
> >>   group_info = 0xffff880104cec420, rcu = {next = 0x0, func =
> >> 0xffffffff810b6c97 <put_cred_rcu>}}
> >>
> >> (gdb) p (char[4])cred->magic
> >> $8 = "DaeD"
> >>
> >>
> >>
> >> --
> >> Robert Święcki
> >> --
> >> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> >> the body of a message to majordomo@vger.kernel.org
> >> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> >> Please read the FAQ at  http://www.tux.org/lkml/
> 
> 
> 
> -- 
> Robert Święcki
> 


^ permalink raw reply	[flat|nested] 4+ messages in thread
* Re: Fw: Badness around put_cred()
       [not found] ` <20120126162820.GA7083@sergelap>
  2012-01-26 23:18   ` Fw: Badness around put_cred() Robert Święcki
@ 2012-01-27 18:13   ` David Howells
  2012-01-27 18:25   ` David Howells
  2 siblings, 0 replies; 4+ messages in thread
From: David Howells @ 2012-01-27 18:13 UTC (permalink / raw)
  To: =?UTF-8?B?Um9iZXJ0IMWad2nEmWNraQ==?=
  Cc: dhowells, Serge Hallyn, Andrew Morton, Paul E. McKenney, linux-kernel

Robert Święcki <robert@swiecki.net> wrote:

> I was fuzzing linux kernel for some time, and there seems to be a bug,
> which kicks in relatively quickly (a few hours at most), which ends up
> with warn() or panic() - depending on options compiled in
> (CONFIG_DEBUG_CREDENTIALS, preemption mode). I was looking briefly
> through kernel code, and I think it might be related to the
> include/linux/cred.h::
>
> static inline void put_cred(const struct cred *_cred)
> {
>         struct cred *cred = (struct cred *) _cred;
>
>         validate_creds(cred);
>         if (atomic_dec_and_test(&(cred)->usage))
>                 __put_cred(cred);
> }
>
> which checks whether the usage counter is different than 0, and maybe
> it should be checking whether it is >0.

The creds should get retired when the usage count reaches 0.  It should never
go negative.

> All in all, I don't understand the whole cred/rcu code yet, so just
> dumping the data, in case somebody else can spot the problem quicker.
> The kernel versions are 2.6.39 and 3.2

I can give you a summary of the way the creds work if you need it:

 (1) A process's UIDs, GIDs, groups list, LSM IDs, key subscriptions, etc. are
     its credentials.  These are separated out so they can be overridden more
     easily.

 (2) A process has *two* pointers to its own creds and normally these point to
     the same set of creds.

     (a) The first set of creds (task->real_cred) specifies how this process
     	 appears to other processes and governs what those other processes are
     	 permitted to do to it.  This set is only changed when the process
     	 itself adjusts its creds (such as calling setuid() or exec()).

     (b) The second set of creds (task->cred) governs how this process acts
     	 towards other objects within the system.  These are normally set to
     	 the same as the first set.  However, the kernel may override these to
     	 perform actions in other contexts without affecting how other
     	 processes act upon this one.

 (3) Each process cred pointers holds a ref on the creds it points to.

 (4) A process may only change its own cred pointers and may not change anyone
     else's.

 (5) A process may only change the first cred pointer (2a) if the second cred
     pointer (2b) is currently the same.

 (6) A process may use its own creds without taking any locks whatsoever due to
     point (4).

 (7) A process must observe RCU COW protocol when updating its cred pointers.

 (8) A process may access another process's creds without taking a ref provided
     it holds the RCU read lock.  These creds may be replaced whilst they are
     being examined.  If that is a problem, some other lock must be used as
     well.

 (9) A process may retain another's creds by taking a ref on them under lock,
     but not the RCU read lock as the cred may have had their last reference
     released since the RCU read lock was taken.

(10) Once a new cred struct has been published (ie. made visible to the rest of
     the system) it may not be changed.

(11) Destruction of a cred struct must be deferred until all currently held RCU
     read locks are released.

David

^ permalink raw reply	[flat|nested] 4+ messages in thread
* Re: Fw: Badness around put_cred()
       [not found] ` <20120126162820.GA7083@sergelap>
  2012-01-26 23:18   ` Fw: Badness around put_cred() Robert Święcki
  2012-01-27 18:13   ` David Howells
@ 2012-01-27 18:25   ` David Howells
  2 siblings, 0 replies; 4+ messages in thread
From: David Howells @ 2012-01-27 18:25 UTC (permalink / raw)
  To: Robert Święcki
  Cc: dhowells, Serge Hallyn, Andrew Morton, Paul E. McKenney, linux-kernel


One thing you could try doing is making do_notify_resume() check the credential
subscriptions on the process as it's about to resume userspace.  The following
assertions both ought to hold:

	BUG_ON(current->cred != current->real_cred);
	BUG_ON(atomic_read(current->cred->usage) >= 2);

And then set TIF_NOTIFY_RESUME in put_cred() and get_new_cred().

David

^ permalink raw reply	[flat|nested] 4+ messages in thread
end of thread, other threads:[~2012-01-27 18:25 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <20120126012626.09ca152f.akpm@linux-foundation.org>
     [not found] ` <20120126162820.GA7083@sergelap>
2012-01-26 23:18   ` Fw: Badness around put_cred() Robert Święcki
2012-01-26 23:31     ` Paul E. McKenney
2012-01-27 18:13   ` David Howells
2012-01-27 18:25   ` David Howells

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).