Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751201AbdFAMeU (ORCPT ); Thu, 1 Jun 2017 08:34:20 -0400 Received: from mx0a-001b2d01.pphosted.com ([148.163.156.1]:51713 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751062AbdFAMeS (ORCPT ); Thu, 1 Jun 2017 08:34:18 -0400 Date: Thu, 1 Jun 2017 14:34:08 +0200 (CEST) From: Sebastian Ott X-X-Sender: sebott@schleppi To: Xin Long cc: "David S. Miller" , Haidong Li , Nikolay Aleksandrov , Ivan Vecera , Stephen Hemminger , network dev , LKML , Heiko Carstens , Martin Schwidefsky Subject: Re: Oops with commit 6d18c73 bridge: start hello_timer when enabling KERNEL_STP in br_stp_start In-Reply-To: References: User-Agent: Alpine 2.20 (LFD 67 2015-01-07) Organization: =?ISO-8859-15?Q?=22IBM_Deutschland_Research_&_Development_GmbH_=2F_Vorsitzende_des_Aufsichtsrats=3A_Martina_Koederitz_Gesch=E4ftsf=FChrung=3A_Dirk_Wittkopp_Sitz_der_Gesellschaft=3A_B=F6blingen_=2F_Registergericht?= =?ISO-8859-15?Q?=3A_Amtsgericht_Stuttgart=2C_HRB_243294=22?= MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII X-TM-AS-GCONF: 00 x-cbid: 17060112-0012-0000-0000-00000542325F X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17060112-0013-0000-0000-000018AE0006 Message-Id: X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:,, definitions=2017-06-01_03:,, signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 spamscore=0 suspectscore=11 malwarescore=0 phishscore=0 adultscore=0 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1703280000 definitions=main-1706010232 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 7936 Lines: 142 On Thu, 1 Jun 2017, Xin Long wrote: > On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott > wrote: > > [...] > I couldn't see any bridge-related thing here, and it couldn't be reproduced > with virbr0 (stp=1) on my box (on both s390x and x86_64), I guess there > is something else in you machine. > > With the latest upstream kernel, can you remove libvirt (virbr0) and boot your > machine normally, then: > # brctl addbr br0 > # ip link set br0 up > # brctl stp br0 on > > to check if it will still hang. Nope. That doesn't hang. > If it can't be reproduced in this way, pls add this on your kernel: > > --- a/net/bridge/br_stp_if.c > +++ b/net/bridge/br_stp_if.c > @@ -178,9 +178,11 @@ static void br_stp_start(struct net_bridge *br) > br->stp_enabled = BR_KERNEL_STP; > br_debug(br, "using kernel STP\n"); > > + WARN_ON(1); > /* To start timers on any ports left in blocking */ > mod_timer(&br->hello_timer, jiffies + br->hello_time); > br_port_state_selection(br); > + pr_warn("hello timer start done\n"); > } > > spin_unlock_bh(&br->lock); > diff --git a/net/bridge/br_stp_timer.c b/net/bridge/br_stp_timer.c > index 60b6fe2..c98b3e5 100644 > --- a/net/bridge/br_stp_timer.c > +++ b/net/bridge/br_stp_timer.c > @@ -40,7 +40,7 @@ static void br_hello_timer_expired(unsigned long arg) > if (br->dev->flags & IFF_UP) { > br_config_bpdu_generation(br); > > - if (br->stp_enabled == BR_KERNEL_STP) > + if (br->stp_enabled != BR_USER_STP) > mod_timer(&br->hello_timer, > round_jiffies(jiffies + br->hello_time)); > > > let's see if it hangs when starting the timer. Thanks. No hang either: [ 134.018104] ------------[ cut here ]------------ [ 134.018144] WARNING: CPU: 1 PID: 1339 at net/bridge/br_stp_if.c:181 br_stp_set_enabled+0x154/0x2b0 [bridge] [ 134.018149] Modules linked in: bridge stp llc rdma_ucm ib_ucm ib_uverbs [...] [ 134.018257] CPU: 1 PID: 1339 Comm: brctl Not tainted 4.12.0-rc3-00011-gf511c0b-dirty #587 [ 134.018262] Hardware name: IBM 2827 H66 705 (LPAR) [ 134.018266] task: 00000000d141c100 task.stack: 00000000d1430000 [ 134.018271] Krnl PSW : 0704f00180000000 000003ff802bc4c4 (br_stp_set_enabled+0x154/0x2b0 [bridge]) [ 134.018286] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 RI:0 EA:3 [ 134.018294] Krnl GPRS: 00000000c5eae501 00000000000005dc 0000000000000bb8 0000000000000001 [ 134.018298] 000003ff802bc42c 00000000d1433c78 0000000000000001 00000000d3ad2d60 [ 134.018303] 0000000000000002 000003ff802c21a8 00000000d3ad2d60 00000000fffffffe [ 134.018308] 00000000d1671738 00000000000026a0 000003ff802bc42c 00000000d1433c38 [ 134.018320] Krnl Code: 000003ff802bc4b4: e54ca9180001 mvhi 2328(%r10),1 000003ff802bc4ba: c00400000000 brcl 0,3ff802bc4ba #000003ff802bc4c0: a7f40001 brc 15,3ff802bc4c2 >000003ff802bc4c4: c418ffffb5aa lgrl %r1,3ff802b3018 000003ff802bc4ca: 4120ac10 la %r2,3088(%r10) 000003ff802bc4ce: e33010000004 lg %r3,0(%r1) 000003ff802bc4d4: e330a8d80008 ag %r3,2264(%r10) 000003ff802bc4da: c0e5ffffbc8b brasl %r14,3ff802b3df0 [ 134.018374] Call Trace: [ 134.018384] ([<000003ff802bc42c>] br_stp_set_enabled+0xbc/0x2b0 [bridge]) [ 134.018393] [<000003ff802c21d2>] set_stp_state+0x2a/0x40 [bridge] [ 134.018402] [<000003ff802c0f30>] store_bridge_parm+0xa8/0xf8 [bridge] [ 134.018410] [<00000000004012f2>] kernfs_fop_write+0x132/0x208 [ 134.018417] [<000000000036088e>] __vfs_write+0x36/0x140 [ 134.018422] [<0000000000361b54>] vfs_write+0xbc/0x1a0 [ 134.018427] [<000000000036323e>] SyS_write+0x66/0xc0 [ 134.018434] [<00000000008ccc80>] system_call+0xc4/0x28c [ 134.018438] 5 locks held by brctl/1339: [ 134.018443] #0: (sb_writers#5){.+.+.+}, at: [<0000000000361b3e>] vfs_write+0xa6/0x1a0 [ 134.018462] #1: (&of->mutex){+.+.+.}, at: [<0000000000401372>] kernfs_fop_write+0x1b2/0x208 [ 134.018478] #2: (s_active#116){.+.+.+}, at: [<000000000040137e>] kernfs_fop_write+0x1be/0x208 [ 134.018496] #3: (rtnl_mutex){+.+.+.}, at: [<000003ff802c0f08>] store_bridge_parm+0x80/0xf8 [bridge] [ 134.018517] #4: (&(&br->lock)->rlock){+.....}, at: [<000003ff802bc42c>] br_stp_set_enabled+0xbc/0x2b0 [bridge] [ 134.018537] Last Breaking-Event-Address: [ 134.018546] [<000003ff802bc4c0>] br_stp_set_enabled+0x150/0x2b0 [bridge] [ 134.018551] ---[ end trace 0fc342e82de9b3d7 ]--- [ 134.018638] hello timer start done In the system dump I observed that 3 cpus are within mod_timer (different timers) and spin for some lock (one of them is the console driver which explains the missing messages). Using a different config with object debugging enabled I got this interesting output: [ 18.759850] virbr0: port 1(virbr0-nic) entered disabled state [ 18.825885] ODEBUG: free active (active state 0) object type: timer_list hint: br_hello_timer_expired+0x0/0xb8 [bridge] [ 18.826081] ------------[ cut here ]------------ [ 18.826085] WARNING: CPU: 1 PID: 519 at lib/debugobjects.c:289 debug_print_object+0xb0/0xd0 [ 18.826087] Modules linked in: bridge stp llc rng_core ghash_s390 prng [...] [ 18.826118] CPU: 1 PID: 519 Comm: libvirtd Not tainted 4.12.0-rc3-00002-g475ef2f #359 [ 18.826120] Hardware name: IBM 2827 H66 705 (LPAR) [ 18.826123] task: 000000006dca4100 task.stack: 000000006e7b0000 [ 18.826125] Krnl PSW : 0404d00180000000 00000000006420d0 (debug_print_object+0xb0/0xd0) [ 18.826131] R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 RI:0 EA:3 [ 18.826135] Krnl GPRS: ffffffffffffffe9 0000000080000001 000000000000006b 0000000000a973f4 [ 18.826138] 0000000000292296 0000000000000000 0000000000a8cca2 0000000001e3bf18 [ 18.826140] 0000000001e3bf10 0000000069c4e2a8 0000000069c4c2a8 0000000000ab2f48 [ 18.826143] 0000000000cc6f18 000000006fce91a8 00000000006420cc 000000006e7b3ad0 [ 18.826152] Krnl Code: 00000000006420c0: c02000242a65 larl %r2,ac758a 00000000006420c6: c0e5ffe280c1 brasl %r14,292248 #00000000006420cc: a7f40001 brc 15,6420ce >00000000006420d0: c41d0032960a lrl %r1,c94ce4 00000000006420d6: e340f0e80004 lg %r4,232(%r15) 00000000006420dc: a71a0001 ahi %r1,1 00000000006420e0: eb6ff0a80004 lmg %r6,%r15,168(%r15) 00000000006420e6: c41f003295ff strl %r1,c94ce4 [ 18.826177] Call Trace: [ 18.826180] ([<00000000006420cc>] debug_print_object+0xac/0xd0) [ 18.826183] [<00000000006431ba>] __debug_check_no_obj_freed+0xca/0x258 [ 18.826185] [<0000000000319a44>] kfree+0x264/0x410 [ 18.826188] [<00000000006a8e46>] device_release+0x76/0xb0 [ 18.826191] [<000000000060e67e>] kobject_put+0xde/0x1d8 [ 18.826194] [<00000000007bd14e>] netdev_run_todo+0x2be/0x2d0 [ 18.826201] [<000003ff8096b762>] br_del_bridge+0x82/0x98 [bridge] [ 18.826208] [<000003ff8096d750>] br_ioctl_deviceless_stub+0x100/0x140 [bridge] [ 18.826211] [<000000000078e562>] sock_ioctl+0x1a2/0x2f0 [ 18.826214] [<000000000035dc3c>] do_vfs_ioctl+0x714/0x7a8 [ 18.826217] [<000000000035dd4c>] SyS_ioctl+0x7c/0xb0 [ 18.826220] [<00000000008f2300>] system_call+0xc4/0x274 [ 18.826222] INFO: lockdep is turned off. [ 18.826224] Last Breaking-Event-Address: [ 18.826227] [<00000000006420cc>] debug_print_object+0xac/0xd0 [ 18.826230] ---[ end trace 765b1870ef16b23f ]--- Regards, Sebastian