xs_tcp_setup_socket: connect returned unhandled error -113 xs_tcp_setup_socket: connect returned unhandled error -113 xs_tcp_setup_socket: connect returned unhandled error -113 ====================================================== WARNING: possible circular locking dependency detected 4.14.0-rc4+ #125 Not tainted ------------------------------------------------------ kworker/0:1/24 is trying to acquire lock: ("xprtiod"){+.+.}, at: [] start_flush_work kernel/workqueue.c:2857 [inline] ("xprtiod"){+.+.}, at: [] flush_work+0x5a2/0x8f0 kernel/workqueue.c:2889 but task is already holding lock: ((&task->u.tk_work)){+.+.}, at: [] process_one_work+0xb2c/0x1bd0 kernel/workqueue.c:2094 which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #1 ((&task->u.tk_work)){+.+.}: check_prevs_add kernel/locking/lockdep.c:2020 [inline] validate_chain kernel/locking/lockdep.c:2469 [inline] __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002 process_one_work+0xba2/0x1bd0 kernel/workqueue.c:2095 worker_thread+0x223/0x1860 kernel/workqueue.c:2253 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 -> #0 ("xprtiod"){+.+.}: check_prev_add+0x865/0x1520 kernel/locking/lockdep.c:1894 check_prevs_add kernel/locking/lockdep.c:2020 [inline] validate_chain kernel/locking/lockdep.c:2469 [inline] __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002 start_flush_work kernel/workqueue.c:2858 [inline] flush_work+0x5c7/0x8f0 kernel/workqueue.c:2889 __cancel_work_timer+0x30a/0x7e0 kernel/workqueue.c:2961 cancel_work_sync+0x17/0x20 kernel/workqueue.c:2997 xprt_destroy+0xa1/0x130 net/sunrpc/xprt.c:1467 xprt_destroy_kref net/sunrpc/xprt.c:1477 [inline] kref_put include/linux/kref.h:70 [inline] xprt_put+0x38/0x40 net/sunrpc/xprt.c:1501 rpc_task_release_client+0x299/0x430 net/sunrpc/clnt.c:986 rpc_release_resources_task+0x7f/0xa0 net/sunrpc/sched.c:1020 rpc_release_task net/sunrpc/sched.c:1059 [inline] __rpc_execute+0x4d9/0xe70 net/sunrpc/sched.c:824 rpc_async_schedule+0x16/0x20 net/sunrpc/sched.c:848 process_one_work+0xbfa/0x1bd0 kernel/workqueue.c:2119 worker_thread+0x223/0x1860 kernel/workqueue.c:2253 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 other info that might help us debug this: Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock((&task->u.tk_work)); lock("xprtiod"); lock((&task->u.tk_work)); lock("xprtiod"); *** DEADLOCK *** 2 locks held by kworker/0:1/24: #0: ("rpciod"){+.+.}, at: [] __write_once_size include/linux/compiler.h:305 [inline] #0: ("rpciod"){+.+.}, at: [] atomic64_set arch/x86/include/asm/atomic64_64.h:33 [inline] #0: ("rpciod"){+.+.}, at: [] atomic_long_set include/asm-generic/atomic-long.h:56 [inline] #0: ("rpciod"){+.+.}, at: [] set_work_data kernel/workqueue.c:617 [inline] #0: ("rpciod"){+.+.}, at: [] set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline] #0: ("rpciod"){+.+.}, at: [] process_one_work+0xad4/0x1bd0 kernel/workqueue.c:2090 #1: ((&task->u.tk_work)){+.+.}, at: [] process_one_work+0xb2c/0x1bd0 kernel/workqueue.c:2094 stack backtrace: CPU: 0 PID: 24 Comm: kworker/0:1 Not tainted 4.14.0-rc4+ #125 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Workqueue: rpciod rpc_async_schedule Call Trace: __dump_stack lib/dump_stack.c:16 [inline] dump_stack+0x194/0x257 lib/dump_stack.c:52 print_circular_bug+0x503/0x710 kernel/locking/lockdep.c:1259 check_prev_add+0x865/0x1520 kernel/locking/lockdep.c:1894 check_prevs_add kernel/locking/lockdep.c:2020 [inline] validate_chain kernel/locking/lockdep.c:2469 [inline] __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002 start_flush_work kernel/workqueue.c:2858 [inline] flush_work+0x5c7/0x8f0 kernel/workqueue.c:2889 __cancel_work_timer+0x30a/0x7e0 kernel/workqueue.c:2961 cancel_work_sync+0x17/0x20 kernel/workqueue.c:2997 xprt_destroy+0xa1/0x130 net/sunrpc/xprt.c:1467 xprt_destroy_kref net/sunrpc/xprt.c:1477 [inline] kref_put include/linux/kref.h:70 [inline] xprt_put+0x38/0x40 net/sunrpc/xprt.c:1501 rpc_task_release_client+0x299/0x430 net/sunrpc/clnt.c:986 rpc_release_resources_task+0x7f/0xa0 net/sunrpc/sched.c:1020 rpc_release_task net/sunrpc/sched.c:1059 [inline] __rpc_execute+0x4d9/0xe70 net/sunrpc/sched.c:824 rpc_async_schedule+0x16/0x20 net/sunrpc/sched.c:848 process_one_work+0xbfa/0x1bd0 kernel/workqueue.c:2119 worker_thread+0x223/0x1860 kernel/workqueue.c:2253 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 audit: type=1326 audit(1507697400.663:2486): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=22121 comm="syz-executor7" exe="/root/syz-executor7" sig=31 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0xffff0000 audit: type=1326 audit(1507697400.814:2487): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=22121 comm="syz-executor7" exe="/root/syz-executor7" sig=31 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0xffff0000 sctp: [Deprecated]: syz-executor1 (pid 22240) Use of int in maxseg socket option. Use struct sctp_assoc_value instead nla_parse: 1 callbacks suppressed netlink: 5 bytes leftover after parsing attributes in process `syz-executor6'. sctp: [Deprecated]: syz-executor1 (pid 22240) Use of struct sctp_assoc_value in delayed_ack socket option. Use struct sctp_sack_info instead netlink: 5 bytes leftover after parsing attributes in process `syz-executor6'. sctp: [Deprecated]: syz-executor1 (pid 22244) Use of int in maxseg socket option. Use struct sctp_assoc_value instead sctp: [Deprecated]: syz-executor1 (pid 22253) Use of struct sctp_assoc_value in delayed_ack socket option. Use struct sctp_sack_info instead 9pnet_virtio: no channels available for device ./bus netlink: 5 bytes leftover after parsing attributes in process `syz-executor5'. 9pnet_virtio: no channels available for device ./bus netlink: 5 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 13 bytes leftover after parsing attributes in process `syz-executor4'. QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl SELinux: unrecognized netlink message: protocol=0 nlmsg_type=14917 sclass=netlink_route_socket pig=22648 comm=syz-executor0 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=14917 sclass=netlink_route_socket pig=22661 comm=syz-executor0 netlink: 1 bytes leftover after parsing attributes in process `syz-executor0'. QAT: Invalid ioctl QAT: Invalid ioctl netlink: 1 bytes leftover after parsing attributes in process `syz-executor0'. kvm: emulating exchange as write syz-executor0: vmalloc: allocation failure: 16587630936 bytes, mode:0x14080c0(GFP_KERNEL|__GFP_ZERO), nodemask=(null) syz-executor0 cpuset=/ mems_allowed=0 CPU: 0 PID: 23012 Comm: syz-executor0 Not tainted 4.14.0-rc4+ #125 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: __dump_stack lib/dump_stack.c:16 [inline] dump_stack+0x194/0x257 lib/dump_stack.c:52 warn_alloc+0x1c2/0x2f0 mm/page_alloc.c:3254 __vmalloc_node_range+0x581/0x710 mm/vmalloc.c:1781 __vmalloc_node mm/vmalloc.c:1810 [inline] __vmalloc_node_flags_caller+0x50/0x60 mm/vmalloc.c:1832 kvmalloc_node+0x82/0xd0 mm/util.c:406 kvmalloc include/linux/mm.h:529 [inline] kvmalloc_array include/linux/mm.h:545 [inline] xt_alloc_entry_offsets+0x21/0x30 net/netfilter/x_tables.c:774 translate_table+0x235/0x1610 net/ipv4/netfilter/ip_tables.c:686 do_replace net/ipv4/netfilter/ip_tables.c:1130 [inline] do_ipt_set_ctl+0x34b/0x5c0 net/ipv4/netfilter/ip_tables.c:1664 nf_sockopt net/netfilter/nf_sockopt.c:105 [inline] nf_setsockopt+0x67/0xc0 net/netfilter/nf_sockopt.c:114 ip_setsockopt+0xa1/0xb0 net/ipv4/ip_sockglue.c:1255 tcp_setsockopt+0x82/0xd0 net/ipv4/tcp.c:2799 sock_common_setsockopt+0x95/0xd0 net/core/sock.c:2965 SYSC_setsockopt net/socket.c:1852 [inline] SyS_setsockopt+0x189/0x360 net/socket.c:1831 entry_SYSCALL_64_fastpath+0x1f/0xbe RIP: 0033:0x4520a9 RSP: 002b:00007fccb2f06c08 EFLAGS: 00000216 ORIG_RAX: 0000000000000036 RAX: ffffffffffffffda RBX: 00000000007180b0 RCX: 00000000004520a9 RDX: 0000000000000040 RSI: 0000000000000000 RDI: 0000000000000019 RBP: 0000000000a6f870 R08: 0000000000000056 R09: 0000000000000000 R10: 0000000020c2c000 R11: 0000000000000216 R12: 0000000000000000 R13: 0000000000a6f7ef R14: 00007fccb2f079c0 R15: 0000000000000019 warn_alloc_show_mem: 1 callbacks suppressed Mem-Info: syz-executor0: vmalloc: allocation failure: 16587630936 bytes, mode:0x14080c0(GFP_KERNEL|__GFP_ZERO), nodemask=(null) syz-executor0 cpuset=/ mems_allowed=0 CPU: 1 PID: 23021 Comm: syz-executor0 Not tainted 4.14.0-rc4+ #125 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: __dump_stack lib/dump_stack.c:16 [inline] dump_stack+0x194/0x257 lib/dump_stack.c:52 warn_alloc+0x1c2/0x2f0 mm/page_alloc.c:3254 __vmalloc_node_range+0x581/0x710 mm/vmalloc.c:1781 __vmalloc_node mm/vmalloc.c:1810 [inline] __vmalloc_node_flags_caller+0x50/0x60 mm/vmalloc.c:1832 kvmalloc_node+0x82/0xd0 mm/util.c:406 kvmalloc include/linux/mm.h:529 [inline] kvmalloc_array include/linux/mm.h:545 [inline] xt_alloc_entry_offsets+0x21/0x30 net/netfilter/x_tables.c:774 translate_table+0x235/0x1610 net/ipv4/netfilter/ip_tables.c:686 do_replace net/ipv4/netfilter/ip_tables.c:1130 [inline] do_ipt_set_ctl+0x34b/0x5c0 net/ipv4/netfilter/ip_tables.c:1664 nf_sockopt net/netfilter/nf_sockopt.c:105 [inline] nf_setsockopt+0x67/0xc0 net/netfilter/nf_sockopt.c:114 ip_setsockopt+0xa1/0xb0 net/ipv4/ip_sockglue.c:1255 tcp_setsockopt+0x82/0xd0 net/ipv4/tcp.c:2799 sock_common_setsockopt+0x95/0xd0 net/core/sock.c:2965 SYSC_setsockopt net/socket.c:1852 [inline] SyS_setsockopt+0x189/0x360 net/socket.c:1831 entry_SYSCALL_64_fastpath+0x1f/0xbe RIP: 0033:0x4520a9 RSP: 002b:00007fccb2ea3c08 EFLAGS: 00000216 ORIG_RAX: 0000000000000036 RAX: ffffffffffffffda RBX: 00000000007182c0 RCX: 00000000004520a9 RDX: 0000000000000040 RSI: 0000000000000000 RDI: 0000000000000021 RBP: 0000000000005e40 R08: 0000000000000056 R09: 0000000000000000 R10: 0000000020c2c000 R11: 0000000000000216 R12: 00000000004bbc62 R13: 00000000ffffffff R14: 00000000202a0000 R15: 0002200000000004 netlink: 16 bytes leftover after parsing attributes in process `syz-executor2'. sctp: [Deprecated]: syz-executor3 (pid 23044) Use of struct sctp_assoc_value in delayed_ack socket option. Use struct sctp_sack_info instead sctp: [Deprecated]: syz-executor3 (pid 23044) Use of struct sctp_assoc_value in delayed_ack socket option. Use struct sctp_sack_info instead SELinux: unrecognized netlink message: protocol=0 nlmsg_type=0 sclass=netlink_route_socket pig=23051 comm=syz-executor2 QAT: Invalid ioctl sock: process `syz-executor3' is using obsolete getsockopt SO_BSDCOMPAT QAT: Invalid ioctl active_anon:129928 inactive_anon:44 isolated_anon:0 active_file:3918 inactive_file:7154 isolated_file:0 unevictable:0 dirty:208 writeback:0 unstable:0 slab_reclaimable:10914 slab_unreclaimable:102533 mapped:22131 shmem:184 pagetables:854 bounce:0 free:1353360 free_pcp:516 free_cma:0 Node 0 active_anon:519712kB inactive_anon:176kB active_file:15672kB inactive_file:28616kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:88524kB dirty:832kB writeback:0kB shmem:736kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 94208kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no Node 0 DMA free:15908kB min:160kB low:200kB high:240kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB lowmem_reserve[]: 0 2886 6399 6399 Node 0 DMA32 free:2957424kB min:30408kB low:38008kB high:45608kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:8kB unevictable:0kB writepending:0kB present:3129332kB managed:2958156kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:732kB local_pcp:652kB free_cma:0kB lowmem_reserve[]: 0 0 3513 3513 Node 0 Normal free:2440108kB min:37008kB low:46260kB high:55512kB active_anon:519712kB inactive_anon:176kB active_file:15672kB inactive_file:51824kB unevictable:0kB writepending:832kB present:4718592kB managed:3597444kB mlocked:0kB kernel_stack:4064kB pagetables:3416kB bounce:0kB free_pcp:1332kB local_pcp:708kB free_cma:0kB lowmem_reserve[]: 0 0 0 0 Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15908kB Node 0 DMA32: 6*4kB (UM) 1*8kB (M) 3*16kB (M) 3*32kB (UM) 5*64kB (UM) 3*128kB (M) 3*256kB (UM) 5*512kB (UM) 2*1024kB (UM) 3*2048kB (UM) 719*4096kB (M) = 2957424kB Node 0 Normal: 185*4kB (UME) 148*8kB (UME) 1632*16kB (UME) 1104*32kB (UME) 884*64kB (UME) 557*128kB (ME) 377*256kB (UME) 122*512kB (UME) 33*1024kB (UME) 4*2048kB (UME) 500*4096kB (M) = 2440196kB Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB 11255 total pagecache pages 0 pages in swap cache Swap cache stats: add 0, delete 0, find 0/0 Free swap = 0kB Total swap = 0kB 1965979 pages RAM 0 pages HighMem/MovableOnly 323102 pages reserved device syz6 entered promiscuous mode device syz6 left promiscuous mode device syz6 entered promiscuous mode device gre0 entered promiscuous mode audit: type=1326 audit(1507697405.810:2488): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 SELinux: unrecognized netlink message: protocol=6 nlmsg_type=515 sclass=netlink_xfrm_socket pig=23238 comm=syz-executor2 audit: type=1326 audit(1507697405.832:2489): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=16 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2490): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2491): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 SELinux: unrecognized netlink message: protocol=6 nlmsg_type=515 sclass=netlink_xfrm_socket pig=23248 comm=syz-executor2 audit: type=1326 audit(1507697405.832:2492): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2493): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2494): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2495): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 audit: type=1326 audit(1507697405.832:2496): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 netlink: 4 bytes leftover after parsing attributes in process `syz-executor3'. netlink: 4 bytes leftover after parsing attributes in process `syz-executor3'. audit: type=1326 audit(1507697405.832:2497): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=23230 comm="syz-executor0" exe="/root/syz-executor0" sig=0 arch=c000003e syscall=202 compat=0 ip=0x4520a9 code=0x50000 netlink: 5 bytes leftover after parsing attributes in process `syz-executor4'. QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl netlink: 5 bytes leftover after parsing attributes in process `syz-executor4'. QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl netlink: 8 bytes leftover after parsing attributes in process `syz-executor3'. netlink: 8 bytes leftover after parsing attributes in process `syz-executor3'. SELinux: unrecognized netlink message: protocol=6 nlmsg_type=515 sclass=netlink_xfrm_socket pig=23401 comm=syz-executor2 SELinux: unrecognized netlink message: protocol=6 nlmsg_type=515 sclass=netlink_xfrm_socket pig=23401 comm=syz-executor2 RDS: rds_bind could not find a transport for 172.20.2.170, load rds_tcp or rds_rdma? RDS: rds_bind could not find a transport for 172.20.2.170, load rds_tcp or rds_rdma? netlink: 3 bytes leftover after parsing attributes in process `syz-executor2'. netlink: 3 bytes leftover after parsing attributes in process `syz-executor2'. netlink: 3 bytes leftover after parsing attributes in process `syz-executor2'. netlink: 3 bytes leftover after parsing attributes in process `syz-executor2'. netlink: 3 bytes leftover after parsing attributes in process `syz-executor2'. QAT: Invalid ioctl QAT: Invalid ioctl SELinux: unrecognized netlink message: protocol=0 nlmsg_type=32767 sclass=netlink_route_socket pig=23715 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=0 sclass=netlink_route_socket pig=23715 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=0 sclass=netlink_route_socket pig=23715 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=202 sclass=netlink_route_socket pig=23721 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=32767 sclass=netlink_route_socket pig=23722 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=0 sclass=netlink_route_socket pig=23728 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=0 sclass=netlink_route_socket pig=23728 comm=syz-executor1 SELinux: unrecognized netlink message: protocol=0 nlmsg_type=202 sclass=netlink_route_socket pig=23729 comm=syz-executor1 sock: sock_set_timeout: `syz-executor1' (pid 23776) tries to set negative timeout sock: sock_set_timeout: `syz-executor1' (pid 23776) tries to set negative timeout