From mboxrd@z Thu Jan 1 00:00:00 1970 From: Sasha Levin Subject: sctp: hang in sctp_remaddr_seq_show Date: Fri, 15 Mar 2013 12:34:00 -0400 Message-ID: <51434D78.9030308@oracle.com> Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Cc: linux-sctp@vger.kernel.org, netdev@vger.kernel.org, Dave Jones , "linux-kernel@vger.kernel.org" To: vyasevich@gmail.com, sri@us.ibm.com, nhorman@tuxdriver.com, "David S. Miller" Return-path: Sender: linux-kernel-owner@vger.kernel.org List-Id: netdev.vger.kernel.org Hi all, While fuzzing with trinity inside a KVM tools guest running latest -next kernel, I've stumbled on an interesting hang related to sctp. After some fuzzing, I get a hang message about procfs not able to grab a hold of a mutex for one of the files: [ 375.900309] INFO: task trinity-child21:7178 blocked for more than 120 seconds. [ 375.901767] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 375.903022] trinity-child21 D ffff88009b9f74a8 5336 7178 7121 0x00000004 [ 375.904211] ffff88009ba79cb8 0000000000000002 ffff8800abf48690 ffff8800abf48690 [ 375.905972] ffff880075308000 ffff88009c798000 ffff88009ba79cb8 00000000001d7140 [ 375.907263] ffff88009c798000 ffff88009ba79fd8 00000000001d7140 00000000001d7140 [ 375.908987] Call Trace: [ 375.909415] [] __schedule+0x2e9/0x3b0 [ 375.910795] [] schedule+0x55/0x60 [ 375.911611] [] schedule_preempt_disabled+0x13/0x20 [ 375.912644] [] __mutex_lock_common+0x36d/0x5a0 [ 375.913986] [] ? seq_read+0x3a/0x3d0 [ 375.914838] [] ? seq_read+0x3a/0x3d0 [ 375.916187] [] ? seq_lseek+0x110/0x110 [ 375.917075] [] mutex_lock_nested+0x3f/0x50 [ 375.918005] [] seq_read+0x3a/0x3d0 [ 375.919124] [] ? delay_tsc+0xdd/0x110 [ 375.920916] [] ? seq_lseek+0x110/0x110 [ 375.921794] [] ? seq_lseek+0x110/0x110 [ 375.922966] [] proc_reg_read+0x201/0x230 [ 375.923870] [] ? proc_reg_write+0x230/0x230 [ 375.924820] [] vfs_read+0xb5/0x180 [ 375.925668] [] SyS_read+0x50/0xa0 [ 375.926476] [] tracesys+0xe1/0xe6 [ 375.940223] 1 lock held by trinity-child21/7178: [ 375.940985] #0: (&p->lock){+.+.+.}, at: [] seq_read+0x3a/0x3d Digging deeper, there's another thread that's stuck holding that lock: [ 381.880804] trinity-child97 R running task 4856 9490 7121 0x00000004 [ 381.882064] ffff880084cad708 0000000000000002 ffff8800bbbd71f8 ffff8800bbbd71f8 [ 381.883341] ffff8800b9490000 ffff88009a5e8000 ffff880084cad708 00000000001d7140 [ 381.884652] ffff88009a5e8000 ffff880084cadfd8 00000000001d7140 00000000001d7140 [ 381.885977] Call Trace: [ 381.886392] [] __schedule+0x2e9/0x3b0 [ 381.887238] [] preempt_schedule+0x44/0x70 [ 381.888175] [] ? sctp_remaddr_seq_show+0x2da/0x2f0 [ 381.889314] [] local_bh_enable+0x128/0x140 [ 381.890292] [] sctp_remaddr_seq_show+0x2da/0x2f0 [ 381.891397] [] ? sctp_remaddr_seq_show+0x27/0x2f0 [ 381.892448] [] ? seq_read+0x3a/0x3d0 [ 381.893308] [] traverse+0xe0/0x1f0 [ 381.894135] [] ? seq_lseek+0x110/0x110 [ 381.895100] [] ? seq_lseek+0x110/0x110 [ 381.896074] [] seq_read+0x5c/0x3d0 [ 381.896912] [] ? delay_tsc+0xdd/0x110 [ 381.897796] [] ? seq_lseek+0x110/0x110 [ 381.898734] [] ? seq_lseek+0x110/0x110 [ 381.899629] [] proc_reg_read+0x201/0x230 [ 381.900592] [] ? proc_reg_write+0x230/0x230 [ 381.901614] [] ? proc_reg_write+0x230/0x230 [ 381.902543] [] do_loop_readv_writev+0x4b/0x90 [ 381.903480] [] do_readv_writev+0xf6/0x1d0 [ 381.904456] [] ? kvm_clock_read+0x38/0x70 [ 381.905460] [] vfs_readv+0x3e/0x60 [ 381.906306] [] default_file_splice_read+0x1e1/0x320 [ 381.907365] [] ? deactivate_slab+0x7d6/0x820 [ 381.908412] [] ? deactivate_slab+0x7d6/0x820 [ 381.909404] [] ? __lock_release+0xf1/0x110 [ 381.910435] [] ? deactivate_slab+0x7d6/0x820 [ 381.911483] [] ? do_raw_spin_unlock+0xc8/0xe0 [ 381.912478] [] ? _raw_spin_unlock+0x30/0x60 [ 381.913438] [] ? deactivate_slab+0x7d6/0x820 [ 381.914478] [] ? alloc_pipe_info+0x3e/0xa0 [ 381.915504] [] ? alloc_pipe_info+0x3e/0xa0 [ 381.916461] [] ? alloc_pipe_info+0x3e/0xa0 [ 381.917418] [] ? __slab_alloc.isra.34+0x2ed/0x31f [ 381.918533] [] ? trace_hardirqs_on_caller+0x168/0x1a0 [ 381.919637] [] ? debug_check_no_locks_freed+0xf5/0x130 [ 381.920799] [] ? page_cache_pipe_buf_release+0x20/0x20 [ 381.921963] [] do_splice_to+0x83/0xb0 [ 381.922849] [] splice_direct_to_actor+0xce/0x1c0 [ 381.923874] [] ? do_splice_from+0xb0/0xb0 [ 381.924855] [] do_splice_direct+0x48/0x60 [ 381.925865] [] do_sendfile+0x165/0x310 [ 381.926763] [] ? trace_hardirqs_on+0xd/0x10 [ 381.927722] [] SyS_sendfile64+0x8a/0xc0 [ 381.928702] [] ? tracesys+0x7e/0xe6 [ 381.929556] [] tracesys+0xe1/0xe6 It has gone to sleep while holding the proc mutex we're trying to acquire and never woke up! Looking at the code, we see: rcu_read_unlock(); read_unlock(&head->lock); sctp_local_bh_enable(); <--- here It hangs on local_bh_enable(). It seems that local_bh_enable() calls preempt_check_resched() which never gets woken up. Why? I have no clue. It's also pretty reproducible with sctp. Thanks, Sasha