Re: net: hang in ip_finish_output

On Fri, Jan 15, 2016 at 12:57 PM, Dmitry Vyukov [off-list ref] wrote:

Hello,

The following program hangs kernel in ip_finish_output (if run in a
parallel loop):

// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <unistd.h>
#include <sys/syscall.h>
#include <string.h>
#include <stdint.h>
#include <pthread.h>

long r[21];

void *thr(void *arg)
{
        switch ((long)arg) {
        case 0:
                r[0] = syscall(SYS_mmap, 0x20000000ul, 0x1d000ul,
0x3ul, 0x32ul, 0xfffffffffffffffful, 0x0ul);
                break;
        case 1:
                r[1] = syscall(SYS_socket, 0x2ul, 0x2ul, 0x0ul, 0, 0, 0);
                break;
        case 2:
                *(uint32_t*)0x20016000 = (uint32_t)0xe4c;
                r[3] = syscall(SYS_setsockopt, r[1], 0x1ul, 0xful,
0x20016000ul, 0x4ul, 0);
                break;
        case 3:
                memcpy((void*)0x20009000,
"\x11\x8d\x57\x62\x7e\xc3\xd8\xb9\xe3\xd8\x63\x4d\x56\x77\x7b\xf1\x3c\x7e\x0c\x91\x62\xca\xc6\x26\xb1\xb9\x11\x34\x6a\xae",
30);
                r[5] = syscall(SYS_pwrite64, r[1], 0x20009000ul,
0x1eul, 0x0ul, 0, 0);
                break;
        case 4:
                memcpy((void*)0x20006f80,
"\x02\x00\x33\xd9\x7f\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00",
128);
                r[7] = syscall(SYS_bind, r[1], 0x20006f80ul, 0x80ul, 0, 0, 0);
                break;
        case 5:
                memcpy((void*)0x20016f80,
"\x02\x00\x33\xd9\x7f\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00",
128);
                r[9] = syscall(SYS_connect, r[1], 0x20016f80ul,
0x80ul, 0, 0, 0);
                break;
        case 6:
                *(uint32_t*)0x20011b08 = (uint32_t)0x18;
                *(uint32_t*)0x20011b0c = (uint32_t)0x2;
                *(uint64_t*)0x20011b10 = (uint64_t)0x0;
                *(uint32_t*)0x20011b18 = (uint32_t)0xfffffffffffffffc;
                r[14] = syscall(SYS_write, r[1], 0x20011b08ul, 0x18ul, 0, 0, 0);
                break;
        case 7:
                r[15] = syscall(SYS_getsockopt, r[1], 0x0ul, 0x3ul,
0x2000b000ul, 0x2000bffful, 0);
                break;
        case 8:
                memcpy((void*)0x20013c04,
"\xdb\x4c\xcc\xa8\x07\xbd\xaa\x58\x7c\x57\x37\x63\xa1\x4d\xdb\x5b\x85\x4e\x37\x3b\x20\xb3\x12\xef\x9b\x75\xf0\x88\x28\xa5\x43\x8e\x56\x59\x3c\x16\xfd\xa0\x01\x4f\x90\x83\x4c\x1b\x22\x3e\xd4\xea\x36\x6f\xb5\x43\x96\x02\x8e\x82\xa1\xc6\x47\xd7\xeb\x08\x56\x6f\x40\xb6\x00\x3f\x52\x38\x99\x2f\x57\x63\x9b\xe4\x0e\xb2\x59\xb2\x59\xbc\x9d\x46\xd0\x52\xd4\x91\xe8\xee\x7f\xcf\x81\xa0\xd5\x10\xc4\x77\xf6\xa1\xa1\x35\xb3\xeb\xb5\x46\xfe\xbc\x83\x74\x9f\x78\xa4\xf1\x0b\xf2\x3a\x41\xc3\x2d\x78\x32\x3b\x88\xe9\xb7\x9f\x56",
128);
                r[17] = syscall(SYS_write, r[1], 0x20013c04ul, 0x80ul, 0, 0, 0);
                break;
        case 9:
                r[18] = syscall(SYS_read, r[1], 0x2001afabul, 0x55ul, 0, 0, 0);
                break;
        case 10:
                memcpy((void*)0x200173b8,
"\x04\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00",
128);
                r[20] = syscall(SYS_recvfrom, r[1], 0x20017000ul,
0xc7ul, 0x0ul, 0x200173b8ul, 0x80ul);
                break;
        }
        return 0;
}

int main()
{
        long i;
        pthread_t th[11];

        memset(r, -1, sizeof(r));
        for (i = 0; i < 11; i++) {
                pthread_create(&th[i], 0, thr, (void*)i);
                usleep(10000);
        }
        for (i = 0; i < 11; i++) {
                pthread_create(&th[i], 0, thr, (void*)i);
                if (i%2==0)
                        usleep(10000);
        }
        usleep(100000);
        return 0;
}


INFO: rcu_sched self-detected stall on CPU
1-...: (1 GPs behind) idle=a8b/140000000000001/0 softirq=83363/83364 fqs=6
(t=26000 jiffies g=29224 c=29223 q=50)
rcu_sched kthread starved for 25980 jiffies! g29224 c29223 f0x0
RCU_GP_WAIT_FQS(3) ->state=0x1
rcu_sched       S ffff88003d827a98 29272     8      2 0x00000000
 ffff88003d827a98 ffff88003ec16d40 ffff88003d80e718 00ffed0007b04f6f
 ffff88003ec20a70 ffff88003ec20a48 ffff88003ec200d8 ffff88003d80df08
 ffff88003ec200c0 ffff880034c517c0 ffff88003d80df00 ffff88003d820000
Call Trace:
 [<ffffffff8625cf27>] schedule+0x97/0x1c0 kernel/sched/core.c:3311
 [<ffffffff86268feb>] schedule_timeout+0x36b/0x920 kernel/time/timer.c:1531
 [<ffffffff814af122>] rcu_gp_kthread+0xad2/0x1b60 kernel/rcu/tree.c:2125
 [<ffffffff813b3b2f>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
 [<ffffffff8626c7ef>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:468
Task dump for CPU 1:
syz-executor    R  running task    27912 26692  11656 0x0000000a
 ffff880036ebed30 ffff88003ed07230 ffffffff813e7289 0000000000000005
 ffff88003ed200c0 0000000000000001 1ffffffff0ebbab0 ffffffff875dd548
 dffffc0000000000 ffff88003ed07250 ffffffff813ef951 ffffffff875dd500
Call Trace:
 <IRQ>  [<ffffffff813e7289>] sched_show_task+0x269/0x3b0
kernel/sched/core.c:5036
 [<ffffffff813ef951>] dump_cpu_task+0x71/0x90 kernel/sched/core.c:8717
 [<ffffffff814a4c71>] rcu_dump_cpu_stacks+0x181/0x270 kernel/rcu/tree.c:1247
 [<     inline     >] print_cpu_stall kernel/rcu/tree.c:1354
 [<     inline     >] check_cpu_stall kernel/rcu/tree.c:1418
 [<     inline     >] __rcu_pending kernel/rcu/tree.c:3906
 [<     inline     >] rcu_pending kernel/rcu/tree.c:3970
 [<ffffffff814b1b90>] rcu_check_callbacks+0xd40/0x1e10 kernel/rcu/tree.c:2795
 [<ffffffff814c23aa>] update_process_times+0x3a/0x70 kernel/time/timer.c:1420
 [<ffffffff814eb8df>] tick_sched_handle.isra.20+0xaf/0xe0
kernel/time/tick-sched.c:151
 [<ffffffff814ec005>] tick_sched_timer+0x75/0x100 kernel/time/tick-sched.c:1086
 [<     inline     >] __run_hrtimer kernel/time/hrtimer.c:1229
 [<ffffffff814c4173>] __hrtimer_run_queues+0x363/0xc10
kernel/time/hrtimer.c:1293
 [<ffffffff814c6172>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1327
 [<ffffffff8124f052>] local_apic_timer_interrupt+0x72/0xe0
arch/x86/kernel/apic/apic.c:907
 [<ffffffff81252579>] smp_apic_timer_interrupt+0x79/0xa0
arch/x86/kernel/apic/apic.c:931
 [<ffffffff8626d22c>] apic_timer_interrupt+0x8c/0xa0
arch/x86/entry/entry_64.S:520
 [<ffffffff814a1244>] rcu_read_lock_held+0xa4/0xc0 kernel/rcu/update.c:293
 [<ffffffff851bdc78>] reuseport_select_sock+0x4a8/0x10c0
net/core/sock_reuseport.c:211
 [<ffffffff85529032>] udp4_lib_lookup2+0x362/0x7a0 net/ipv4/udp.c:518
 [<ffffffff8552a09d>] __udp4_lib_lookup+0x26d/0xd20 net/ipv4/udp.c:576
 [<     inline     >] __udp4_lib_lookup_skb net/ipv4/udp.c:651
 [<ffffffff85530785>] __udp4_lib_rcv+0x1135/0x23e0 net/ipv4/udp.c:1891
 [<ffffffff85532f91>] udp_rcv+0x21/0x30 net/ipv4/udp.c:2108
 [<ffffffff8545dd03>] ip_local_deliver_finish+0x2b3/0xa50
net/ipv4/ip_input.c:216
 [<     inline     >] NF_HOOK_THRESH include/linux/netfilter.h:226
 [<     inline     >] NF_HOOK include/linux/netfilter.h:249
 [<ffffffff8545eba4>] ip_local_deliver+0x1c4/0x2f0 net/ipv4/ip_input.c:257
 [<     inline     >] dst_input include/net/dst.h:498
 [<ffffffff8545c90c>] ip_rcv_finish+0x5ec/0x1730 net/ipv4/ip_input.c:365
 [<     inline     >] NF_HOOK_THRESH include/linux/netfilter.h:226
 [<     inline     >] NF_HOOK include/linux/netfilter.h:249
 [<ffffffff8545f633>] ip_rcv+0x963/0x1080 net/ipv4/ip_input.c:455
 [<ffffffff85165850>] __netif_receive_skb_core+0x1620/0x2f80 net/core/dev.c:4149
 [<ffffffff851671da>] __netif_receive_skb+0x2a/0x160 net/core/dev.c:4184
 [<ffffffff851675be>] process_backlog+0x2ae/0x820 net/core/dev.c:4765
 [<     inline     >] napi_poll net/core/dev.c:5069
 [<ffffffff8516cc9b>] net_rx_action+0x7eb/0xdf0 net/core/dev.c:5134
 [<ffffffff813615ca>] __do_softirq+0x26a/0x920 kernel/softirq.c:273
 [<ffffffff8626e35c>] do_softirq_own_stack+0x1c/0x30
arch/x86/entry/entry_64.S:875
 <EOI>  [<ffffffff8135fbb4>] do_softirq.part.22+0x104/0x130 kernel/softirq.c:317
 [<     inline     >] do_softirq kernel/softirq.c:165
 [<ffffffff8135fe62>] __local_bh_enable_ip+0x142/0x190 kernel/softirq.c:170
 [<     inline     >] local_bh_enable include/linux/bottom_half.h:31
 [<     inline     >] rcu_read_unlock_bh include/linux/rcupdate.h:970
 [<ffffffff854702c3>] ip_finish_output2+0x703/0x11a0 net/ipv4/ip_output.c:211
 [<ffffffff8547405d>] ip_finish_output+0x7bd/0xd00 net/ipv4/ip_output.c:283
 [<     inline     >] NF_HOOK_COND include/linux/netfilter.h:240
 [<ffffffff85477778>] ip_output+0x218/0x460 net/ipv4/ip_output.c:357
 [<     inline     >] dst_output include/net/dst.h:492
 [<ffffffff85474a3b>] ip_local_out+0xdb/0x1c0 net/ipv4/ip_output.c:115
 [<ffffffff8547a21c>] ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1439
 [<ffffffff85521506>] udp_send_skb+0x326/0xbf0 net/ipv4/udp.c:914
 [<ffffffff8552b43e>] udp_sendmsg+0x87e/0x1e70 net/ipv4/udp.c:1139
 [<ffffffff855590f7>] inet_sendmsg+0x2f7/0x4c0 net/ipv4/af_inet.c:736
 [<     inline     >] sock_sendmsg_nosec net/socket.c:611
 [<ffffffff8510417a>] sock_sendmsg+0xca/0x110 net/socket.c:621
 [<ffffffff851043d6>] sock_write_iter+0x216/0x3a0 net/socket.c:820
 [<     inline     >] new_sync_write fs/read_write.c:517
 [<ffffffff8178d122>] __vfs_write+0x302/0x480 fs/read_write.c:530
 [<ffffffff8178e9c7>] vfs_write+0x167/0x4a0 fs/read_write.c:577
 [<     inline     >] SYSC_write fs/read_write.c:624
 [<ffffffff81791cb1>] SyS_write+0x111/0x220 fs/read_write.c:616
 [<ffffffff8626c436>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185

On commit 67990608c8b95d2b8ccc29932376ae73d5818727 (Jan 12).

I wasn't able to reproduce this exact stack trace, but I was able to
cause soft lockup messages with a fork bomb of your test program.  It
is certainly related to my recent SO_REUSEPORT change (reverting it
seems to fix the problem).  I haven't completely figured out the exact
cause yet, though.  Could you please post your configuration and
exactly how you are running this 'parallel loop'?

Craig