From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752109AbcFUN77 (ORCPT ); Tue, 21 Jun 2016 09:59:59 -0400 Received: from mail-io0-f176.google.com ([209.85.223.176]:35579 "EHLO mail-io0-f176.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751609AbcFUN74 (ORCPT ); Tue, 21 Jun 2016 09:59:56 -0400 To: Peter Zijlstra , Ingo Molnar , LKML From: David Ahern Subject: chain_key collision with 4.7.0-rec2+ Message-ID: <8650ca98-24e9-20c3-f1e5-033ccdface2f@cumulusnetworks.com> Date: Tue, 21 Jun 2016 07:03:58 -0600 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:45.0) Gecko/20100101 Thunderbird/45.1.1 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Peter/Ingo: I have this hit many times over the past few weeks, but I do not have a reliable reproducer to attempt a git bisect. There 2 dumps below I hit last night within a few minutes of each other (reboot in between). First dump is for ipv4 (first login to VM after boot) and second dump is for ipv6 (second login to VM after boot). Both are using net-next tree, top commit is 697666eac66. IPv4 one: [ 189.120375] ------------[ cut here ]------------ [ 189.121476] WARNING: CPU: 2 PID: 1463 at ../kernel/locking/lockdep.c:2099 validate_chain.isra.37+0x25b/0xa5b [ 189.123420] DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id) [ 189.124641] Modules linked in: [ 189.125353] CPU: 2 PID: 1463 Comm: sshd Not tainted 4.7.0-rc2+ #310 [ 189.126614] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014 [ 189.128600] 0000000000000000 ffff8800b977b718 ffffffff8127e51e ffff8800b977b768 [ 189.130173] 0000000000000000 ffff8800b977b758 ffffffff8104d190 00000833b977b7d0 [ 189.131804] ffffffff81decec0 0000000000006519 01a1c10e0898ad0c ffff8800bac64680 [ 189.133277] Call Trace: [ 189.133759] [] dump_stack+0x81/0xb6 [ 189.134718] [] __warn+0xc5/0xe0 [ 189.135611] [] warn_slowpath_fmt+0x46/0x4e [ 189.136681] [] validate_chain.isra.37+0x25b/0xa5b [ 189.137874] [] ? kvm_clock_read+0x25/0x2e [ 189.138932] [] ? kvm_sched_clock_read+0x9/0x12 [ 189.140084] [] ? paravirt_sched_clock+0x9/0xd [ 189.141193] [] __lock_acquire+0x5e4/0x690 [ 189.142130] [] ? __lock_acquire+0x5e4/0x690 [ 189.143006] [] lock_acquire+0x140/0x1d8 [ 189.143832] [] ? sch_direct_xmit+0x6f/0x167 [ 189.144712] [] _raw_spin_lock+0x2f/0x65 [ 189.145547] [] ? sch_direct_xmit+0x6f/0x167 [ 189.146426] [] sch_direct_xmit+0x6f/0x167 [ 189.147276] [] __dev_queue_xmit+0x43b/0x72d [ 189.148154] [] ? eth_header+0x27/0xaf [ 189.148960] [] dev_queue_xmit+0xb/0xd [ 189.149768] [] neigh_resolve_output+0x113/0x12e [ 189.150722] [] ip_finish_output2+0x3c0/0x41c [ 189.151619] [] ip_finish_output+0x132/0x13e [ 189.152548] [] NF_HOOK_COND.constprop.43+0x21/0x8a [ 189.153557] [] ? lock_is_held+0x69/0x70 [ 189.154347] [] ? rcu_read_lock_held+0x29/0x2f [ 189.155200] [] ip_output+0x65/0x6a [ 189.155920] [] dst_output+0x2b/0x30 [ 189.156649] [] ip_local_out+0x2a/0x31 [ 189.157425] [] ip_queue_xmit+0x2c3/0x315 [ 189.158223] [] tcp_transmit_skb+0x696/0x6c5 [ 189.159048] [] tcp_write_xmit+0x820/0xb1c [ 189.159863] [] ? __might_fault+0xa0/0xa2 [ 189.160659] [] ? copy_from_iter+0x1cb/0x296 [ 189.161493] [] __tcp_push_pending_frames+0x2b/0x67 [ 189.162409] [] tcp_push+0x94/0xff [ 189.163176] [] tcp_sendmsg+0x775/0x83a [ 189.164006] [] inet_sendmsg+0x35/0x5c [ 189.164760] [] sock_sendmsg_nosec+0x12/0x1d [ 189.165556] [] sock_write_iter+0x75/0x8d [ 189.166324] [] __vfs_write+0x77/0xa0 [ 189.167040] [] vfs_write+0xa2/0xc6 [ 189.167723] [] SyS_write+0x4b/0x79 [ 189.168437] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 189.169318] [] ? trace_hardirqs_off_caller+0xbc/0x122 [ 189.170247] ---[ end trace 24ee736782fa0dbd ]--- [ 189.170870] [ 189.171084] ====================== [ 189.171555] [chain_key collision ] [ 189.172020] 4.7.0-rc2+ #310 Tainted: G W [ 189.172729] ---------------------- [ 189.173192] sshd/1463: Hash chain already cached but the contents don't match! [ 189.174236] Held locks:depth: 6 [ 189.174707] class_idx:1253 -> chain_key:00000000000004e5 (sk_lock-AF_INET){+.+.+.}, at: [] lock_sock+0xb/0xd [ 189.176376] class_idx:26 -> chain_key:00000000009ca01a (rcu_read_lock){......}, at: [] rcu_lock_acquire+0x0/0x20 [ 189.178014] class_idx:898 -> chain_key:0000001394034382 (rcu_read_lock_bh){......}, at: [] rcu_lock_acquire+0x0/0x20 [ 189.179712] class_idx:898 -> chain_key:0002728068704382 (rcu_read_lock_bh){......}, at: [] rcu_lock_acquire+0x0/0x20 [ 189.181374] class_idx:1221 -> chain_key:4e500d0e087044c5 (dev->qdisc_running_key ?: &qdisc_running_key){+.....}, at: [] __dev_queue_xmit+0x40c/0x72d [ 189.183400] class_idx:1222 -> chain_key:01a1c10e0898ad0c (_xmit_ETHER#2){+.-...}, at: [] sch_direct_xmit+0x6f/0x167 [ 189.185178] Locks in cached chain:depth: 6 [ 189.185791] class_idx:1252 -> chain_key:00000000000004e4 (((&ndev->rs_timer))){+.-...} [ 189.186957] class_idx:26 -> chain_key:00000000009c801a (rcu_read_lock){......} [ 189.187991] class_idx:898 -> chain_key:0000001390034382 (rcu_read_lock_bh){......} [ 189.189023] class_idx:898 -> chain_key:0002720068704382 (rcu_read_lock_bh){......} [ 189.190050] class_idx:1221 -> chain_key:4e400d0e087044c5 (dev->qdisc_running_key ?: &qdisc_running_key){+.....} [ 189.191370] class_idx:1220 -> chain_key:01a1c10e0898ad0c (&(&list->lock)->rlock#3){+.-...} [ 189.192503] [ 189.192503] stack backtrace: [ 189.193052] CPU: 2 PID: 1463 Comm: sshd Tainted: G W 4.7.0-rc2+ #310 [ 189.193988] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014 [ 189.195242] 0000000000000000 ffff8800b977b778 ffffffff8127e51e 00000000000004c3 [ 189.196237] ffffffff81decec0 ffff8800b977b7c0 ffffffff81083212 000000040000c410 [ 189.197219] ffff8800bac64ed8 ffffffff81decec0 0000000000006519 01a1c10e0898ad0c [ 189.198215] Call Trace: [ 189.198535] [] dump_stack+0x81/0xb6 [ 189.199176] [] print_collision+0x203/0x210 [ 189.199909] [] validate_chain.isra.37+0x4eb/0xa5b [ 189.200696] [] ? kvm_clock_read+0x25/0x2e [ 189.201399] [] ? kvm_sched_clock_read+0x9/0x12 [ 189.202167] [] ? paravirt_sched_clock+0x9/0xd [ 189.202917] [] __lock_acquire+0x5e4/0x690 [ 189.203626] [] ? __lock_acquire+0x5e4/0x690 [ 189.204359] [] lock_acquire+0x140/0x1d8 [ 189.205046] [] ? sch_direct_xmit+0x6f/0x167 [ 189.205781] [] _raw_spin_lock+0x2f/0x65 [ 189.206464] [] ? sch_direct_xmit+0x6f/0x167 [ 189.207199] [] sch_direct_xmit+0x6f/0x167 [ 189.207912] [] __dev_queue_xmit+0x43b/0x72d [ 189.208638] [] ? eth_header+0x27/0xaf [ 189.209299] [] dev_queue_xmit+0xb/0xd [ 189.209983] [] neigh_resolve_output+0x113/0x12e [ 189.210764] [] ip_finish_output2+0x3c0/0x41c [ 189.211505] [] ip_finish_output+0x132/0x13e [ 189.212233] [] NF_HOOK_COND.constprop.43+0x21/0x8a [ 189.213045] [] ? lock_is_held+0x69/0x70 [ 189.213743] [] ? rcu_read_lock_held+0x29/0x2f [ 189.214497] [] ip_output+0x65/0x6a [ 189.215130] [] dst_output+0x2b/0x30 [ 189.215771] [] ip_local_out+0x2a/0x31 [ 189.216430] [] ip_queue_xmit+0x2c3/0x315 [ 189.217131] [] tcp_transmit_skb+0x696/0x6c5 [ 189.217864] [] tcp_write_xmit+0x820/0xb1c [ 189.218566] [] ? __might_fault+0xa0/0xa2 [ 189.219257] [] ? copy_from_iter+0x1cb/0x296 [ 189.219974] [] __tcp_push_pending_frames+0x2b/0x67 [ 189.220770] [] tcp_push+0x94/0xff [ 189.221385] [] tcp_sendmsg+0x775/0x83a [ 189.222066] [] inet_sendmsg+0x35/0x5c [ 189.222732] [] sock_sendmsg_nosec+0x12/0x1d [ 189.223448] [] sock_write_iter+0x75/0x8d [ 189.224137] [] __vfs_write+0x77/0xa0 [ 189.224802] [] vfs_write+0xa2/0xc6 [ 189.225423] [] SyS_write+0x4b/0x79 [ 189.226067] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 189.226887] [] ? trace_hardirqs_off_caller+0xbc/0x122 and IPv6: [ 22.027086] WARNING: CPU: 2 PID: 1401 at ../kernel/locking/lockdep.c:2099 validate_chain.isra.37+0x25b/0xa5b [ 22.029313] DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id) [ 22.030724] Modules linked in: [ 22.031538] CPU: 2 PID: 1401 Comm: sshd Not tainted 4.7.0-rc2+ #310 [ 22.032986] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014 [ 22.035192] 0000000000000000 ffff88013a06b678 ffffffff8127e51e ffff88013a06b6c8 [ 22.036874] 0000000000000000 ffff88013a06b6b8 ffffffff8104d190 000008333a06b730 [ 22.038563] ffffffff81decea0 0000000000005088 01a1c10e0898ed06 ffff8800b97026c0 [ 22.040238] Call Trace: [ 22.040726] [] dump_stack+0x81/0xb6 [ 22.041687] [] __warn+0xc5/0xe0 [ 22.042586] [] warn_slowpath_fmt+0x46/0x4e [ 22.043646] [] validate_chain.isra.37+0x25b/0xa5b [ 22.044852] [] ? kvm_clock_read+0x25/0x2e [ 22.045912] [] ? kvm_sched_clock_read+0x9/0x12 [ 22.047059] [] ? paravirt_sched_clock+0x9/0xd [ 22.048093] [] ? sched_clock+0x9/0xb [ 22.048982] [] __lock_acquire+0x5e4/0x690 [ 22.049933] [] ? __lock_acquire+0x5e4/0x690 [ 22.050910] [] lock_acquire+0x140/0x1d8 [ 22.051830] [] ? sch_direct_xmit+0x6f/0x167 [ 22.052817] [] _raw_spin_lock+0x2f/0x65 [ 22.053738] [] ? sch_direct_xmit+0x6f/0x167 [ 22.054708] [] sch_direct_xmit+0x6f/0x167 [ 22.055666] [] __dev_queue_xmit+0x43b/0x72d [ 22.056658] [] ? ip6_finish_output2+0x311/0x3ee [ 22.057704] [] dev_queue_xmit+0xb/0xd [ 22.058584] [] ip6_finish_output2+0x38c/0x3ee [ 22.059582] [] ? __lock_is_held+0x38/0x50 [ 22.060553] [] ? lock_is_held+0x69/0x70 [ 22.061497] [] ip6_finish_output+0x96/0x9d [ 22.062471] [] ip6_output+0x80/0xe9 [ 22.063327] [] ? __lock_is_held+0x38/0x50 [ 22.064222] [] ? lock_is_held+0x69/0x70 [ 22.065112] [] dst_output+0x2b/0x30 [ 22.065939] [] ip6_xmit+0x322/0x3dd [ 22.066759] [] ? __lock_is_held+0x38/0x50 [ 22.067669] [] inet6_csk_xmit+0xe8/0x118 [ 22.068569] [] tcp_transmit_skb+0x696/0x6c5 [ 22.069491] [] tcp_write_xmit+0x820/0xb1c [ 22.070387] [] ? __might_fault+0xa0/0xa2 [ 22.071272] [] ? copy_from_iter+0x1cb/0x296 [ 22.072194] [] __tcp_push_pending_frames+0x2b/0x67 [ 22.073229] [] tcp_push+0x94/0xff [ 22.074020] [] tcp_sendmsg+0x775/0x83a [ 22.074851] [] inet_sendmsg+0x35/0x5c [ 22.075663] [] sock_sendmsg_nosec+0x12/0x1d [ 22.076555] [] sock_write_iter+0x75/0x8d [ 22.077399] [] __vfs_write+0x77/0xa0 [ 22.078186] [] vfs_write+0xa2/0xc6 [ 22.078948] [] SyS_write+0x4b/0x79 [ 22.079713] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 22.080694] [] ? trace_hardirqs_off_caller+0xbc/0x122 [ 22.081688] ---[ end trace 6df0ce86bcf51c7f ]--- [ 22.082375] [ 22.082615] ====================== [ 22.083126] [chain_key collision ] [ 22.083646] 4.7.0-rc2+ #310 Tainted: G W [ 22.084410] ---------------------- [ 22.084927] sshd/1401: Hash chain already cached but the contents don't match! [ 22.086010] Held locks:depth: 6 [ 22.086509] class_idx:1255 -> chain_key:00000000000004e7 (sk_lock-AF_INET6){+.+.+.}, at: [] lock_sock+0xb/0xd [ 22.088253] class_idx:26 -> chain_key:00000000009ce01a (rcu_read_lock){......}, at: [] rcu_read_lock+0x0/0x68 [ 22.089999] class_idx:898 -> chain_key:000000139c034382 (rcu_read_lock_bh){......}, at: [] rcu_lock_acquire+0x0/0x20 [ 22.091811] class_idx:898 -> chain_key:0002738068704382 (rcu_read_lock_bh){......}, at: [] rcu_lock_acquire+0x0/0x20 [ 22.093639] class_idx:1223 -> chain_key:4e700d0e087044c7 (dev->qdisc_running_key ?: &qdisc_running_key){+.....}, at: [] __dev_queue_xmit+0x40c/0x72d [ 22.095824] class_idx:1224 -> chain_key:01a1c10e0898ed06 (_xmit_ETHER#2){+.-...}, at: [] sch_direct_xmit+0x6f/0x167 [ 22.097616] Locks in cached chain:depth: 6 [ 22.098197] class_idx:1248 -> chain_key:00000000000004e0 (((&ndev->rs_timer))){+.-...} [ 22.099345] class_idx:26 -> chain_key:00000000009c001a (rcu_read_lock){......} [ 22.100419] class_idx:898 -> chain_key:0000001380034382 (rcu_read_lock_bh){......} [ 22.101535] class_idx:898 -> chain_key:0002700068704382 (rcu_read_lock_bh){......} [ 22.102656] class_idx:1223 -> chain_key:4e000d0e087044c7 (dev->qdisc_running_key ?: &qdisc_running_key){+.....} [ 22.104095] class_idx:1222 -> chain_key:01a1c10e0898ed06 (&(&list->lock)->rlock#3){+.-...} [ 22.105325] [ 22.105325] stack backtrace: [ 22.105917] CPU: 2 PID: 1401 Comm: sshd Tainted: G W 4.7.0-rc2+ #310 [ 22.106930] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014 [ 22.108258] 0000000000000000 ffff88013a06b6d8 ffffffff8127e51e 00000000000004c5 [ 22.109295] ffffffff81decea0 ffff88013a06b720 ffffffff81083212 0000000400000002 [ 22.110312] ffff8800b9702f18 ffffffff81decea0 0000000000005088 01a1c10e0898ed06 [ 22.111339] Call Trace: [ 22.111666] [] dump_stack+0x81/0xb6 [ 22.112356] [] print_collision+0x203/0x210 [ 22.113103] [] validate_chain.isra.37+0x4eb/0xa5b [ 22.113929] [] ? kvm_clock_read+0x25/0x2e [ 22.114667] [] ? kvm_sched_clock_read+0x9/0x12 [ 22.115458] [] ? paravirt_sched_clock+0x9/0xd [ 22.116233] [] ? sched_clock+0x9/0xb [ 22.116920] [] __lock_acquire+0x5e4/0x690 [ 22.117652] [] ? __lock_acquire+0x5e4/0x690 [ 22.118732] [] lock_acquire+0x140/0x1d8 [ 22.119481] [] ? sch_direct_xmit+0x6f/0x167 [ 22.120252] [] _raw_spin_lock+0x2f/0x65 [ 22.120981] [] ? sch_direct_xmit+0x6f/0x167 [ 22.121741] [] sch_direct_xmit+0x6f/0x167 [ 22.122453] [] __dev_queue_xmit+0x43b/0x72d [ 22.123188] [] ? ip6_finish_output2+0x311/0x3ee [ 22.123959] [] dev_queue_xmit+0xb/0xd [ 22.124633] [] ip6_finish_output2+0x38c/0x3ee [ 22.125385] [] ? __lock_is_held+0x38/0x50 [ 22.126098] [] ? lock_is_held+0x69/0x70 [ 22.126786] [] ip6_finish_output+0x96/0x9d [ 22.127503] [] ip6_output+0x80/0xe9 [ 22.128143] [] ? __lock_is_held+0x38/0x50 [ 22.128867] [] ? lock_is_held+0x69/0x70 [ 22.129551] [] dst_output+0x2b/0x30 [ 22.130191] [] ip6_xmit+0x322/0x3dd [ 22.130837] [] ? __lock_is_held+0x38/0x50 [ 22.131541] [] inet6_csk_xmit+0xe8/0x118 [ 22.132238] [] tcp_transmit_skb+0x696/0x6c5 [ 22.132971] [] tcp_write_xmit+0x820/0xb1c [ 22.133686] [] ? __might_fault+0xa0/0xa2 [ 22.134386] [] ? copy_from_iter+0x1cb/0x296 [ 22.135116] [] __tcp_push_pending_frames+0x2b/0x67 [ 22.135924] [] tcp_push+0x94/0xff [ 22.136568] [] tcp_sendmsg+0x775/0x83a [ 22.137239] [] inet_sendmsg+0x35/0x5c [ 22.137914] [] sock_sendmsg_nosec+0x12/0x1d [ 22.138643] [] sock_write_iter+0x75/0x8d [ 22.139352] [] __vfs_write+0x77/0xa0 [ 22.140012] [] vfs_write+0xa2/0xc6 [ 22.140668] [] SyS_write+0x4b/0x79 [ 22.141307] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 22.142109] [] ? trace_hardirqs_off_caller+0xbc/0x122