From mboxrd@z Thu Jan  1 00:00:00 1970
From: Craig Gallek <kraigatgoog@gmail.com>
Subject: Re: net: hang in ip_finish_output
Date: Fri, 15 Jan 2016 19:20:56 -0500
Message-ID: <CAEfhGixTRfTviSiaiqYHPDxxz2af4Xbm198WuM1dR6BQKojPxQ@mail.gmail.com>
References: <CACT4Y+bdpCR_rmiDAUi8ge3iecBOpaAat6S3o_GDjt-p2c53BA@mail.gmail.com>
Mime-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8BIT
Cc: "David S. Miller" <davem@davemloft.net>,
	netdev <netdev@vger.kernel.org>,
	LKML <linux-kernel@vger.kernel.org>
To: Dmitry Vyukov <dvyukov@google.com>
Return-path: <linux-kernel-owner@vger.kernel.org>
In-Reply-To: <CACT4Y+bdpCR_rmiDAUi8ge3iecBOpaAat6S3o_GDjt-p2c53BA@mail.gmail.com>
Sender: linux-kernel-owner@vger.kernel.org
List-Id: netdev.vger.kernel.org

On Fri, Jan 15, 2016 at 12:57 PM, Dmitry Vyukov <dvyukov@google.com> 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