Re: run_timer_softirq gpf. [smc]
On Tue, 21 Mar 2017, Dave Jones wrote:
> On Tue, Mar 21, 2017 at 08:25:39PM +0100, Thomas Gleixner wrote:
>
> > > I just hit this while fuzzing..
> > >
> > > general protection fault: [#1] PREEMPT SMP DEBUG_PAGEALLOC
> > > CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.11.0-rc2-think+ #1
> > > task: 88017f0ed440 task.stack: c9094000
> > > RIP: 0010:run_timer_softirq+0x15f/0x700
> > > RSP: 0018:880507c03ec8 EFLAGS: 00010086
> > > RAX: dead0200 RBX: 880507dd0d00 RCX: 0002
> > > RDX: 880507c03ed0 RSI: RDI: 8204b3a0
> > > RBP: 880507c03f48 R08: 880507dd12d0 R09: 880507c03ed8
> > > R10: 880507dd0db0 R11: R12: 8215cc38
> > > R13: 880507c03ed0 R14: 82005188 R15: 8804b55491a8
> > > FS: () GS:880507c0()
> knlGS:
> > > CS: 0010 DS: ES: CR0: 80050033
> > > CR2: 0004 CR3: 05011000 CR4: 001406e0
> > > Call Trace:
> > >
> > > ? clockevents_program_event+0x47/0x120
> > > __do_softirq+0xbf/0x5b1
> > > irq_exit+0xb5/0xc0
> > > smp_apic_timer_interrupt+0x3d/0x50
> > > apic_timer_interrupt+0x97/0xa0
> > > RIP: 0010:cpuidle_enter_state+0x12e/0x400
> > > RSP: 0018:c9097e40 EFLAGS: 0202
> > > [CONT START] ORIG_RAX: ff10
> > > RAX: 88017f0ed440 RBX: e8a03cc8 RCX: 0001
> > > RDX: 20c49ba5e353f7cf RSI: 0001 RDI: 88017f0ed440
> > > RBP: c9097e80 R08: R09: 0008
> > > R10: R11: R12: 0005
> > > R13: 820b9338 R14: 0005 R15: 820b9320
> > >
> > > cpuidle_enter+0x17/0x20
> > > call_cpuidle+0x23/0x40
> > > do_idle+0xfb/0x200
> > > cpu_startup_entry+0x71/0x80
> > > start_secondary+0x16a/0x210
> > > start_cpu+0x14/0x14
> > > Code: 8b 05 ce 1b ef 7e 83 f8 03 0f 87 4e 01 00 00 89 c0 49 0f a3 04 24
> 0f 82 0a 01 00 00 49 8b 07 49 8b 57 08 48 85 c0 48 89 02 74 04 <48> 89 50 08
> 41 f6 47 2a 20 49 c7 47 08 00 00 00 00 48 89 df 48
> >
> > The timer which expires has timer->entry.next == POISON2 !
> >
> > it's a classic list corruption. The
> > bad news is that there is no trace of the culprit because that happens when
> > some other timer expires after some random amount of time.
> >
> > If that is reproducible, then please enable debugobjects. That should
> > pinpoint the culprit.
>
> It's net/smc. This recently had a similar bug with workqueues.
> (https://marc.info/?l=linux-kernel=148821582909541) fixed by
> 637fdbae60d6cb9f6e963c1079d7e0445c86ff7d
Fixed? It's not fixed by that commit. The workqueue code merily got a new
WARN_ON_ONCE(). But the underlying problem is still unfixed in net/smc
> so it's probably unsurprising that there are similar issues.
That one is related to workqueues:
> WARNING: CPU: 0 PID: 2430 at lib/debugobjects.c:289
> debug_print_object+0x87/0xb0
> ODEBUG: free active (active state 0) object type: timer_list hint:
> delayed_work_timer_fn+0x0/0x20
delayed_work_timer_fn() is what queues the work once the timer expires.
> CPU: 0 PID: 2430 Comm: trinity-c4 Not tainted 4.11.0-rc3-think+ #3
> Call Trace:
> dump_stack+0x68/0x93
> __warn+0xcb/0xf0
> warn_slowpath_fmt+0x5f/0x80
> ? debug_check_no_obj_freed+0xd9/0x260
> debug_print_object+0x87/0xb0
> ? work_on_cpu+0xd0/0xd0
> debug_check_no_obj_freed+0x219/0x260
> ? __sk_destruct+0x10d/0x1c0
> kmem_cache_free+0x9f/0x370
> __sk_destruct+0x10d/0x1c0
> sk_destruct+0x20/0x30
> __sk_free+0x43/0xa0
> sk_free+0x18/0x20
smc_release does at the end of the function:
if (smc->use_fallback) {
schedule_delayed_work(>sock_put_work, TCP_TIMEWAIT_LEN);
} else if (sk->sk_state == SMC_CLOSED) {
smc_conn_free(>conn);
schedule_delayed_work(>sock_put_work,
SMC_CLOSE_SOCK_PUT_DELAY);
}
sk->sk_prot->unhash(sk);
release_sock(sk);
sock_put(sk);
sock_put(sk)
{
if (atomic_dec_and_test(>sk_refcnt))
sk_free(sk);
}
That means either smc_release() queued delayed work or it was already
queued.
But in neither case it holds an extra refcount on sk. Otherwise sock_put()
would not end up in sk_free().
Thanks,
tglx
Re: run_timer_softirq gpf. [smc]
On Tue, Mar 21, 2017 at 08:25:39PM +0100, Thomas Gleixner wrote:
> > I just hit this while fuzzing..
> >
> > general protection fault: [#1] PREEMPT SMP DEBUG_PAGEALLOC
> > CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.11.0-rc2-think+ #1
> > task: 88017f0ed440 task.stack: c9094000
> > RIP: 0010:run_timer_softirq+0x15f/0x700
> > RSP: 0018:880507c03ec8 EFLAGS: 00010086
> > RAX: dead0200 RBX: 880507dd0d00 RCX: 0002
> > RDX: 880507c03ed0 RSI: RDI: 8204b3a0
> > RBP: 880507c03f48 R08: 880507dd12d0 R09: 880507c03ed8
> > R10: 880507dd0db0 R11: R12: 8215cc38
> > R13: 880507c03ed0 R14: 82005188 R15: 8804b55491a8
> > FS: () GS:880507c0()
> > knlGS:
> > CS: 0010 DS: ES: CR0: 80050033
> > CR2: 0004 CR3: 05011000 CR4: 001406e0
> > Call Trace:
> >
> > ? clockevents_program_event+0x47/0x120
> > __do_softirq+0xbf/0x5b1
> > irq_exit+0xb5/0xc0
> > smp_apic_timer_interrupt+0x3d/0x50
> > apic_timer_interrupt+0x97/0xa0
> > RIP: 0010:cpuidle_enter_state+0x12e/0x400
> > RSP: 0018:c9097e40 EFLAGS: 0202
> > [CONT START] ORIG_RAX: ff10
> > RAX: 88017f0ed440 RBX: e8a03cc8 RCX: 0001
> > RDX: 20c49ba5e353f7cf RSI: 0001 RDI: 88017f0ed440
> > RBP: c9097e80 R08: R09: 0008
> > R10: R11: R12: 0005
> > R13: 820b9338 R14: 0005 R15: 820b9320
> >
> > cpuidle_enter+0x17/0x20
> > call_cpuidle+0x23/0x40
> > do_idle+0xfb/0x200
> > cpu_startup_entry+0x71/0x80
> > start_secondary+0x16a/0x210
> > start_cpu+0x14/0x14
> > Code: 8b 05 ce 1b ef 7e 83 f8 03 0f 87 4e 01 00 00 89 c0 49 0f a3 04 24 0f
> > 82 0a 01 00 00 49 8b 07 49 8b 57 08 48 85 c0 48 89 02 74 04 <48> 89 50 08
> > 41 f6 47 2a 20 49 c7 47 08 00 00 00 00 48 89 df 48
>
> The timer which expires has timer->entry.next == POISON2 !
>
> it's a classic list corruption. The
> bad news is that there is no trace of the culprit because that happens when
> some other timer expires after some random amount of time.
>
> If that is reproducible, then please enable debugobjects. That should
> pinpoint the culprit.
It's net/smc. This recently had a similar bug with workqueues.
(https://marc.info/?l=linux-kernel=148821582909541) fixed by
637fdbae60d6cb9f6e963c1079d7e0445c86ff7d
so it's probably unsurprising that there are similar issues.
WARNING: CPU: 0 PID: 2430 at lib/debugobjects.c:289 debug_print_object+0x87/0xb0
ODEBUG: free active (active state 0) object type: timer_list hint:
delayed_work_timer_fn+0x0/0x20
CPU: 0 PID: 2430 Comm: trinity-c4 Not tainted 4.11.0-rc3-think+ #3
Call Trace:
dump_stack+0x68/0x93
__warn+0xcb/0xf0
warn_slowpath_fmt+0x5f/0x80
? debug_check_no_obj_freed+0xd9/0x260
debug_print_object+0x87/0xb0
? work_on_cpu+0xd0/0xd0
debug_check_no_obj_freed+0x219/0x260
? __sk_destruct+0x10d/0x1c0
kmem_cache_free+0x9f/0x370
__sk_destruct+0x10d/0x1c0
sk_destruct+0x20/0x30
__sk_free+0x43/0xa0
sk_free+0x18/0x20
smc_release+0x100/0x1a0 [smc]
sock_release+0x1f/0x80
sock_close+0x12/0x20
__fput+0xf3/0x200
fput+0xe/0x10
task_work_run+0x85/0xb0
do_exit+0x331/0xd70
__secure_computing+0x9c/0xa0
syscall_trace_enter+0xd1/0x3d0
do_syscall_64+0x15f/0x1d0
entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7f535f4b19e7
RSP: 002b:7fff1a0f40e8 EFLAGS: 0246
ORIG_RAX: 0008
RAX: ffda RBX: 0004 RCX: 7f535f4b19e7
RDX: RSI: RDI: 0004
RBP: R08: 7f535fb8b000 R09: 00c17c2740a303e4
R10: R11: 0246 R12: 7fff1a0f40f5
R13: 7f535fb60048 R14: 7f535fb83ad8 R15: 7f535fb6
---[ end trace ee67155de15508db ]---
==
[ INFO: possible circular locking dependency detected ]
4.11.0-rc3-think+ #3 Not tainted
---
trinity-c4/2430 is trying to acquire lock:
(
(console_sem).lock
){-.-...}
, at: [] down_trylock+0x14/0x40
but task is already holding lock:
(
_hash[i].lock
){-.-.-.}
, at: [] debug_check_no_obj_freed+0xd9/0x260
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #3
(
_hash[i].lock
){-.-.-.}
:
lock_acquire+0x102/0x260
_raw_spin_lock_irqsave+0x4c/0x90
__debug_object_init+0x79/0x460
debug_object_init+0x16/0x20
hrtimer_init+0x25/0x1d0
init_dl_task_timer+0x20/0x30
__sched_fork.isra.91+0x9c/0x140
init_idle+0x51/0x240
sched_init+0x4cd/0x547
start_kernel+0x246/0x45d
x86_64_start_reservations+0x2a/0x2c
x86_64_start_kernel+0x178/0x18b
