Message-ID: <CAAeHK+x3bw0hCtwAJ4HxMVNhNdNyvMmh_L4V9pcGMvPLOuoH2Q@mail.gmail.com>
Date:   Fri, 21 Apr 2017 15:18:19 +0200
From:   Andrey Konovalov <andreyknvl@...gle.com>
To:     Thomas Gleixner <tglx@...utronix.de>,
        LKML <linux-kernel@...r.kernel.org>
Cc:     Dmitry Vyukov <dvyukov@...gle.com>,
        Kostya Serebryany <kcc@...gle.com>,
        syzkaller <syzkaller@...glegroups.com>
Subject: time: hang due to timer_create/timer_settime

Hi,

I've got the following error report while fuzzing the kernel with syzkaller.

On commit 4f7d029b9bf009fbee76bb10c0c4351a1870d2f3 (4.11-rc7).

A reproducer and .config are attached.

The program hangs the kernel.

INFO: rcu_sched detected stalls on CPUs/tasks:
1-...: (1 ticks this GP) idle=755/140000000000002/0 softirq=12391/12391 fqs=5905
(detected by 0, t=26002 jiffies, g=4729, c=4728, q=6237)
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 9418 Comm: blkid Not tainted 4.11.0-rc7+ #250
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003daa2dc0 task.stack: ffff880039318000
RIP: 0010:atomic_inc arch/x86/include/asm/atomic.h:91 [inline]
RIP: 0010:__lock_acquire+0x297/0x36b0 kernel/locking/lockdep.c:3239
RSP: 0018:ffff88003ed05cc8 EFLAGS: 00000006
RAX: ffffffff869563e0 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 1ffffffff0dcce6b RSI: 0000000000000000 RDI: ffffffff86e67358
RBP: ffff88003ed06208 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000000000 R11: ffffffff86e64f00 R12: ffff88003daa2dc0
R13: 0000000000000000 R14: 0000000000000001 R15: ffffffff86e67350
FS:  0000000000000000(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020715fe0 CR3: 0000000005822000 CR4: 00000000000006e0
DR0: 0000000020000000 DR1: 0000000020000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
Call Trace:
 <IRQ>
 lock_acquire+0x22d/0x560 kernel/locking/lockdep.c:3762
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0xc4/0x110 kernel/locking/spinlock.c:159
 alarmtimer_fired+0x169/0x7a0 kernel/time/alarmtimer.c:189
 __run_hrtimer kernel/time/hrtimer.c:1212 [inline]
 __hrtimer_run_queues+0x350/0xe50 kernel/time/hrtimer.c:1276
 hrtimer_interrupt+0x1ab/0x5c0 kernel/time/hrtimer.c:1310
 local_apic_timer_interrupt+0x6f/0xe0 arch/x86/kernel/apic/apic.c:937
 smp_apic_timer_interrupt+0x71/0xa0 arch/x86/kernel/apic/apic.c:961
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:487
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:778 [inline]
RIP: 0010:__slab_alloc+0x5e/0x90 mm/slub.c:2622
RSP: 0018:ffff88003ed06cc0 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000020 RBX: 0000000000000286 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000286
RBP: ffff88003ed06cf0 R08: ffffe8ffd0b10670 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003db160c0
R13: 0000000001080020 R14: 00000000ffffffff R15: ffffffff834357dd
 slab_alloc_node mm/slub.c:2684 [inline]
 slab_alloc mm/slub.c:2726 [inline]
 kmem_cache_alloc+0x1f8/0x250 mm/slub.c:2731
 __build_skb+0x9d/0x430 net/core/skbuff.c:309
 __napi_alloc_skb+0x32a/0x450 net/core/skbuff.c:511
 napi_alloc_skb include/linux/skbuff.h:2504 [inline]
 e1000_alloc_rx_skb drivers/net/ethernet/intel/e1000/e1000_main.c:4136 [inline]
 e1000_copybreak drivers/net/ethernet/intel/e1000/e1000_main.c:4356 [inline]
 e1000_clean_rx_irq+0x765/0x1490
drivers/net/ethernet/intel/e1000/e1000_main.c:4408
 e1000_clean+0xb9a/0x28f0 drivers/net/ethernet/intel/e1000/e1000_main.c:3834
 napi_poll net/core/dev.c:5267 [inline]
 net_rx_action+0xe70/0x1900 net/core/dev.c:5332
 __do_softirq+0x2fb/0xb7d kernel/softirq.c:284
 invoke_softirq kernel/softirq.c:364 [inline]
 irq_exit+0x19e/0x1d0 kernel/softirq.c:405
 exiting_irq arch/x86/include/asm/apic.h:657 [inline]
 do_IRQ+0x81/0x1a0 arch/x86/kernel/irq.c:250
 common_interrupt+0x93/0x93 arch/x86/entry/entry_64.S:487
RIP: 0010:filter_irq_stacks mm/kasan/kasan.c:496 [inline]
RIP: 0010:save_stack+0x64/0xd0 mm/kasan/kasan.c:514
RSP: 0018:ffff88003931f368 EFLAGS: 00000297 ORIG_RAX: ffffffffffffffc5
RAX: 000000000000000b RBX: 0000000001000000 RCX: 000000000000000c
RDX: ffffffffffffffff RSI: ffff88003931f380 RDI: ffffffff84d4e2a0
RBP: ffff88003931f588 R08: 1ffff10007b547fb R09: ffff88003931f320
R10: ffff88003931f310 R11: ffff88003931f300 R12: ffff8800354d6d68
R13: ffff8800354d6f58 R14: ffffffff817fd722 R15: 0000000000000202
 </IRQ>
 ? entry_SYSCALL_64_fastpath
Lost 137 message(s)!

Another trace of the hang:

INFO: rcu_sched detected stalls on CPUs/tasks:
1-...: (1 GPs behind) idle=6c5/140000000000001/0 softirq=14428/14429 fqs=6023
(detected by 2, t=26002 jiffies, g=6589, c=6588, q=749)
Sending NMI from CPU 2 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 12632 Comm: syz-executor3 Not tainted 4.10.0+ #82
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88004c24db40 task.stack: ffff88004cdc0000
RIP: 0010:__hrtimer_run_queues+0x465/0xe50 kernel/time/hrtimer.c:1254
RSP: 0018:ffff88003ed07c88 EFLAGS: 00000046
RAX: 1ffff100064769e2 RBX: ffff8800323b4ef0 RCX: 0000000000000000
RDX: 0000000000010000 RSI: ffff88003ed1c5d0 RDI: ffff8800323b4f10
RBP: ffff88003ed07ef8 R08: 0000000000000001 R09: 0000000000000001
R10: ffff88003ed1c4d8 R11: dffffc0000000000 R12: 1ffff10007da0fd2
R13: ffff88003ed1c4c0 R14: dffffc0000000000 R15: 0000000000000000
FS:  00007fc912137700(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f0952d85db8 CR3: 000000003d08e000 CR4: 00000000000006e0
DR0: 0000000020000000 DR1: 0000000020000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
Call Trace:
 <IRQ>
 hrtimer_interrupt+0x1ab/0x5c0 kernel/time/hrtimer.c:1308
 local_apic_timer_interrupt+0x6f/0xe0 arch/x86/kernel/apic/apic.c:937
 smp_apic_timer_interrupt+0x71/0xa0 arch/x86/kernel/apic/apic.c:961
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:487
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:778 [inline]
RIP: 0010:__raw_spin_unlock_irqrestore
include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0x119/0x1a0 kernel/locking/spinlock.c:191
RSP: 0018:ffff88004cdc7bb0 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffff100099b8fa2 RBX: 1ffff100099b8f76 RCX: 0000000000000000
RDX: 1ffff100099b8f9a RSI: 0000000000000001 RDI: 0000000000000286
RBP: ffff88004cdc7d70 R08: ffff88007fff705c R09: 0000000000000000
R10: 0000000000000000 R11: ffff88007fff705d R12: dffffc0000000000
R13: 0000000000000286 R14: ffff8800323b4e68 R15: ffff88004cdc7de0
 </IRQ>
 spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
 unlock_timer kernel/time/posix-timers.c:202 [inline]
 SYSC_timer_settime kernel/time/posix-timers.c:912 [inline]
 SyS_timer_settime+0x351/0x5a0 kernel/time/posix-timers.c:881
 entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x4458d9
RSP: 002b:00007fc912136b58 EFLAGS: 00000282 ORIG_RAX: 00000000000000df
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004458d9
RDX: 000000002003ffe0 RSI: 0000000000000001 RDI: 0000000000000000
RBP: 00000000006e2e70 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000020054fe0 R11: 0000000000000282 R12: 00000000007080a8
R13: 0000000000000000 R14: 00007fc9121379c0 R15: 00007fc912137700
Code: 09 00 00 48 8b 85 f0 fd ff ff 48 8b 18 48 85 db 0f 84 0f 04 00
00 e8 2b d2 0f 00 48 8d 7b 20 48 89 f8 48 c1 e8 03 42 80 3c 30 00 <0f>
85 85 09 00 00 48 8b 85 c8 fd ff ff 4c 8b 63 20 48 c1 e8 03

Download attachment ".config" of type "application/octet-stream" (127239 bytes)

View attachment "timer-hang-poc.c" of type "text/x-csrc" (2293 bytes)

Powered by blists - more mailing lists