On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott
<[email protected]> wrote:
[...]
>
> A system running v4.12-rc3-11-gf511c0b on s390 hangs after boot with no
> messages on the console. The message buffer obtained via a system dump
> looked like this:
>
> [...]
> [ 17.870712] virbr0: port 1(virbr0-nic) entered disabled state
> [ 19.618523] Unable to handle kernel pointer dereference in virtual kernel address space
> [ 250.028426] INFO: task jbd2/dasda1-8:100 blocked for more than 120 seconds.
> [ 250.028427] Not tainted 4.12.0-rc3-00011-gf511c0b #573
> [ 250.028428] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 250.028429] jbd2/dasda1-8 D12808 100 2 0x00000000
> [ 250.028437] Stack:
> [ 250.028437] 00000000e8c4f9b0 0000000000000000 0000000000233afe 00000000e8c48100
> [ 250.028441] 00000000e8c4f978 00000000001b1c98 00000000e8c4f978 00000000e8c4f9d8
> [ 250.028444] 04000000efdcce00 00000000e8c48890 0000000000000000 00000000efdcce18
> [ 250.028447] 00000000e8c48100 00000000efdcce00 00000000e8ce8100 00000000e73c6900
> [ 250.028450] 00000000008da090 00000000008c4f54 00000000e8c4f9d8 00000000e8c4fa60
> [ 250.028453] Call Trace:
> [ 250.028458] ([<00000000008c4f54>] __schedule+0xb14/0xc90)
> [ 250.028459] [<00000000008c5164>] schedule+0x94/0xc0
> [ 250.028462] [<00000000001802ac>] io_schedule+0x34/0x58
> [ 250.028464] [<00000000002a44c2>] wait_on_page_bit+0x16a/0x198
> [ 250.028465] [<00000000002a4576>] __filemap_fdatawait_range+0x86/0x188
> [ 250.028467] [<00000000002a46a6>] filemap_fdatawait_range+0x2e/0x58
> [ 250.028471] [<00000000004719d4>] jbd2_journal_commit_transaction+0x10e4/0x2200
> [ 250.028473] [<000000000047890a>] kjournald2+0xda/0x2c0
> [ 250.028475] [<000000000016da5e>] kthread+0x166/0x178
> [ 250.028477] [<00000000008cce7a>] kernel_thread_starter+0x6/0xc
> [ 250.028479] [<00000000008cce74>] kernel_thread_starter+0x0/0xc
> [ 250.028480] INFO: lockdep is turned off.
> [...]
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.
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.
On Thu, 1 Jun 2017, Xin Long wrote:
> On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott
> <[email protected]> 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
On 01/06/17 15:34, Sebastian Ott wrote:
> On Thu, 1 Jun 2017, Xin Long wrote:
>> On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott
>> <[email protected]> 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:
>
[snip]
Could you please try the patch below ?
---
diff --git a/net/bridge/br_stp_if.c b/net/bridge/br_stp_if.c
index 4efd5d54498a..89110319ef0f 100644
--- a/net/bridge/br_stp_if.c
+++ b/net/bridge/br_stp_if.c
@@ -173,7 +173,8 @@ static void br_stp_start(struct net_bridge *br)
br_debug(br, "using kernel STP\n");
/* To start timers on any ports left in blocking */
- mod_timer(&br->hello_timer, jiffies + br->hello_time);
+ if (br->dev->flags & IFF_UP)
+ mod_timer(&br->hello_timer, jiffies + br->hello_time);
br_port_state_selection(br);
}
On 01/06/17 17:00, Nikolay Aleksandrov wrote:
> On 01/06/17 15:34, Sebastian Ott wrote:
>> On Thu, 1 Jun 2017, Xin Long wrote:
>>> On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott
>>> <[email protected]> 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:
>>
> [snip]
> Could you please try the patch below ?
>
> ---
>
> diff --git a/net/bridge/br_stp_if.c b/net/bridge/br_stp_if.c
> index 4efd5d54498a..89110319ef0f 100644
> --- a/net/bridge/br_stp_if.c
> +++ b/net/bridge/br_stp_if.c
> @@ -173,7 +173,8 @@ static void br_stp_start(struct net_bridge *br)
> br_debug(br, "using kernel STP\n");
>
> /* To start timers on any ports left in blocking */
> - mod_timer(&br->hello_timer, jiffies + br->hello_time);
> + if (br->dev->flags & IFF_UP)
> + mod_timer(&br->hello_timer, jiffies + br->hello_time);
> br_port_state_selection(br);
> }
>
>
Ah nevermind, this patch reverts it back to the previous state.
On 01/06/17 17:16, Nikolay Aleksandrov wrote:
> On 01/06/17 17:00, Nikolay Aleksandrov wrote:
>> On 01/06/17 15:34, Sebastian Ott wrote:
>>> On Thu, 1 Jun 2017, Xin Long wrote:
>>>> On Thu, Jun 1, 2017 at 12:32 AM, Sebastian Ott
>>>> <[email protected]> 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:
>>>
>> [snip]
>> Could you please try the patch below ?
>>
>> ---
>>
>> diff --git a/net/bridge/br_stp_if.c b/net/bridge/br_stp_if.c
>> index 4efd5d54498a..89110319ef0f 100644
>> --- a/net/bridge/br_stp_if.c
>> +++ b/net/bridge/br_stp_if.c
>> @@ -173,7 +173,8 @@ static void br_stp_start(struct net_bridge *br)
>> br_debug(br, "using kernel STP\n");
>>
>> /* To start timers on any ports left in blocking */
>> - mod_timer(&br->hello_timer, jiffies + br->hello_time);
>> + if (br->dev->flags & IFF_UP)
>> + mod_timer(&br->hello_timer, jiffies + br->hello_time);
>> br_port_state_selection(br);
>> }
>>
>>
>
> Ah nevermind, this patch reverts it back to the previous state.
>
Okay, I saw the problem and can reliably reproduce it. I will send a fix for testing
in a few minutes. I think the issue is that the timer can be started before the bridge
even goes up, i.e. create bridge -> brctl stp br0 on -> ip l del br0
so the del_timer_sync() doesn't get executed and thus it's still armed.
$ while :; do ip l add br0 type bridge hello_time 100; brctl stp br0 on; ip l del br0; done;