Re: bond: take rcu lock in netpoll_send_skb_on_dev

2018-10-18 Thread Eran Ben Elisha 


On 10/18/2018 8:46 AM, Cong Wang wrote:
> On Mon, Oct 15, 2018 at 4:36 AM Eran Ben Elisha  wrote:
>> Hi,
>>
>> This suggested fix introduced a regression while using netconsole module
>> with mlx5_core module loaded.
> 
> It is already reported here:
> https://marc.info/?l=linux-kernel&m=153917359528669&w=2
> 
> 
>>
>> During irq handling, we hit a warning that this rcu_read_lock_bh cannot
>> be taken inside an IRQ.
> 
> Yes, I mentioned the same even before this patch was sent out:
> https://marc.info/?l=linux-netdev&m=153816136624679&w=2

Thanks Cong.
 From the discussion, I understand that the solution shouldn't be 
touching  netpoll_send_skb_on_dev. Some modules/drivers logging will now 
trigger traces while netconsole is loaded.

DaveJ,
Can you please submit a proper fix or at least revert the current one in 
the meanwhile.

Thanks,
Eran

> 
> Thanks.
>

Re: bond: take rcu lock in netpoll_send_skb_on_dev

2018-10-17 Thread Cong Wang 
On Mon, Oct 15, 2018 at 4:36 AM Eran Ben Elisha  wrote:
> Hi,
>
> This suggested fix introduced a regression while using netconsole module
> with mlx5_core module loaded.

It is already reported here:
https://marc.info/?l=linux-kernel&m=153917359528669&w=2


>
> During irq handling, we hit a warning that this rcu_read_lock_bh cannot
> be taken inside an IRQ.

Yes, I mentioned the same even before this patch was sent out:
https://marc.info/?l=linux-netdev&m=153816136624679&w=2

Thanks.

Re: bond: take rcu lock in netpoll_send_skb_on_dev

2018-10-15 Thread Eran Ben Elisha 


On 9/28/2018 11:26 PM, Dave Jones wrote:
> The bonding driver lacks the rcu lock when it calls down into
> netdev_lower_get_next_private_rcu from bond_poll_controller, which
> results in a trace like:
> 
> WARNING: CPU: 2 PID: 179 at net/core/dev.c:6567 
> netdev_lower_get_next_private_rcu+0x34/0x40
> CPU: 2 PID: 179 Comm: kworker/u16:15 Not tainted 4.19.0-rc5-backup+ #1
> Workqueue: bond0 bond_mii_monitor
> RIP: 0010:netdev_lower_get_next_private_rcu+0x34/0x40
> Code: 48 89 fb e8 fe 29 63 ff 85 c0 74 1e 48 8b 45 00 48 81 c3 c0 00 00 00 48 
> 8b 00 48 39 d8 74 0f 48 89 45 00 48 8b 40 f8 5b 5d c3 <0f> 0b eb de 31 c0 eb 
> f5 0f 1f 40 00 0f 1f 44 00 00 48 8>
> RSP: 0018:c987fa68 EFLAGS: 00010046
> RAX:  RBX: 880429614560 RCX: 
> RDX: 0001 RSI:  RDI: a184ada0
> RBP: c987fa80 R08: 0001 R09: 
> R10: c987f9f0 R11: 880429798040 R12: 8804289d5980
> R13: a1511f60 R14: 00c8 R15: 
> FS:  () GS:88042f88() knlGS:
> CS:  0010 DS:  ES:  CR0: 80050033
> CR2: 7f4b78fce180 CR3: 00018180f006 CR4: 001606e0
> Call Trace:
>   bond_poll_controller+0x52/0x170
>   netpoll_poll_dev+0x79/0x290
>   netpoll_send_skb_on_dev+0x158/0x2c0
>   netpoll_send_udp+0x2d5/0x430
>   write_ext_msg+0x1e0/0x210
>   console_unlock+0x3c4/0x630
>   vprintk_emit+0xfa/0x2f0
>   printk+0x52/0x6e
>   ? __netdev_printk+0x12b/0x220
>   netdev_info+0x64/0x80
>   ? bond_3ad_set_carrier+0xe9/0x180
>   bond_select_active_slave+0x1fc/0x310
>   bond_mii_monitor+0x709/0x9b0
>   process_one_work+0x221/0x5e0
>   worker_thread+0x4f/0x3b0
>   kthread+0x100/0x140
>   ? process_one_work+0x5e0/0x5e0
>   ? kthread_delayed_work_timer_fn+0x90/0x90
>   ret_from_fork+0x24/0x30
> 
> We're also doing rcu dereferences a layer up in netpoll_send_skb_on_dev
> before we call down into netpoll_poll_dev, so just take the lock there.
> 
> Suggested-by: Cong Wang 
> Signed-off-by: Dave Jones 
> 
> diff --git a/net/core/netpoll.c b/net/core/netpoll.c
> index 3219a2932463..692367d7c280 100644
> --- a/net/core/netpoll.c
> +++ b/net/core/netpoll.c
> @@ -330,6 +330,7 @@ void netpoll_send_skb_on_dev(struct netpoll *np, struct 
> sk_buff *skb,
>   /* It is up to the caller to keep npinfo alive. */
>   struct netpoll_info *npinfo;
>   
> + rcu_read_lock_bh();
Hi,

This suggested fix introduced a regression while using netconsole module 
with mlx5_core module loaded.

During irq handling, we hit a warning that this rcu_read_lock_bh cannot 
be taken inside an IRQ.
Isn't it accepted from a driver to print to kernel log inside irq 
handler or maybe the lock was taken too high in the calling chain of 
bond_poll_controller?

Attached below the trace we are hitting once we applied your patch over 
our systems.

[2018-10-15 10:45:30] mlx5_core :00:09.0: firmware version: 16.22.8010
[2018-10-15 10:45:30] mlx5_core :00:09.0: 63.008 Gb/s available PCIe 
bandwidth, limited by 8 GT/s x8 link at :00:09.0 (capable of 126.016 
Gb/s with 8 GT/s x16 link)
[2018-10-15 10:45:31] (:00:09.0): E-Switch: Total vports 1, per 
vport: max uc(1024) max mc(16384)
[2018-10-15 10:45:31] mlx5_core :00:09.0: Port module event: module 
0, Cable plugged
[2018-10-15 10:45:31] WARNING: CPU: 1 PID: 0 at kernel/softirq.c:168 
__local_bh_enable_ip+0x35/0x50
[2018-10-15 10:45:31] Modules linked in: mlx5_core(+) mlxfw bonding 
ip6_gre ip6_tunnel tunnel6 ip_gre ip_tunnel gre rdma_ucm ib_uverbs 
ib_ipoib ib_umad nfsv3 nfs_acl nfs lockd grace fscache netconsole 
mlx4_ib mlx4_en ptp pps_core mlx4_core cfg80211 devlink rfkill rpcrdma 
ib_isert iscsi_target_mod ib_iser ib_srpt target_core_mod ib_srp sunrpc 
rdma_cm ib_cm iw_cm ib_core snd_hda_codec_generic snd_hda_intel 
snd_hda_codec snd_hda_core snd_hwdep snd_seq snd_seq_device snd_pcm 
snd_timer snd soundcore pcspkr i2c_piix4 sch_fq_codel ip_tables cirrus 
drm_kms_helper ata_generic pata_acpi syscopyarea sysfillrect sysimgblt 
fb_sys_fops ttm drm virtio_net net_failover i2c_core failover serio_raw 
floppy ata_piix [last unloaded: mlxfw]
[2018-10-15 10:45:31] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 
4.19.0-rc6-J4083-G9e91d710a170 #1
[2018-10-15 10:45:31] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2011
[2018-10-15 10:45:31] RIP: 0010:__local_bh_enable_ip+0x35/0x50
[2018-10-15 10:45:31] Code: 7e a9 00 00 0f 00 75 22 83 ee 01 f7 de 65 01 
35 91 8c f7 7e 65 8b 05 8a 8c f7 7e a9 00 ff 1f 00 74 0c 65 ff 0d 7c 8c 
f7 7e c3 <0f> 0b eb da 65 66 8b 05 1f 4e f8 7e 66 85 c0 74 e7 e8 55 ff ff ff
[2018-10-15 10:45:31] RSP: 0018:880237a43c10 EFLAGS: 00010006
[2018-10-15 10:45:31] RAX: 80010200 RBX: 0006 RCX: 
0001
[2018-10-15 10:45:31] RDX:  RSI: 0200 RDI: 
817a1321
[2018-10-15 10:45:31] RBP: 880237a43c60 R08: 00480020 R09:

Re: bond: take rcu lock in netpoll_send_skb_on_dev

2018-10-01 Thread David Miller 
From: Dave Jones 
Date: Fri, 28 Sep 2018 16:26:08 -0400

> The bonding driver lacks the rcu lock when it calls down into
> netdev_lower_get_next_private_rcu from bond_poll_controller, which
> results in a trace like:
 ...
> We're also doing rcu dereferences a layer up in netpoll_send_skb_on_dev
> before we call down into netpoll_poll_dev, so just take the lock there.
> 
> Suggested-by: Cong Wang 
> Signed-off-by: Dave Jones 

Applied and queued up for -stable.

bond: take rcu lock in netpoll_send_skb_on_dev

2018-09-28 Thread Dave Jones 
The bonding driver lacks the rcu lock when it calls down into
netdev_lower_get_next_private_rcu from bond_poll_controller, which
results in a trace like:

WARNING: CPU: 2 PID: 179 at net/core/dev.c:6567 
netdev_lower_get_next_private_rcu+0x34/0x40
CPU: 2 PID: 179 Comm: kworker/u16:15 Not tainted 4.19.0-rc5-backup+ #1
Workqueue: bond0 bond_mii_monitor
RIP: 0010:netdev_lower_get_next_private_rcu+0x34/0x40
Code: 48 89 fb e8 fe 29 63 ff 85 c0 74 1e 48 8b 45 00 48 81 c3 c0 00 00 00 48 
8b 00 48 39 d8 74 0f 48 89 45 00 48 8b 40 f8 5b 5d c3 <0f> 0b eb de 31 c0 eb f5 
0f 1f 40 00 0f 1f 44 00 00 48 8>
RSP: 0018:c987fa68 EFLAGS: 00010046
RAX:  RBX: 880429614560 RCX: 
RDX: 0001 RSI:  RDI: a184ada0
RBP: c987fa80 R08: 0001 R09: 
R10: c987f9f0 R11: 880429798040 R12: 8804289d5980
R13: a1511f60 R14: 00c8 R15: 
FS:  () GS:88042f88() knlGS:
CS:  0010 DS:  ES:  CR0: 80050033
CR2: 7f4b78fce180 CR3: 00018180f006 CR4: 001606e0
Call Trace:
 bond_poll_controller+0x52/0x170
 netpoll_poll_dev+0x79/0x290
 netpoll_send_skb_on_dev+0x158/0x2c0
 netpoll_send_udp+0x2d5/0x430
 write_ext_msg+0x1e0/0x210
 console_unlock+0x3c4/0x630
 vprintk_emit+0xfa/0x2f0
 printk+0x52/0x6e
 ? __netdev_printk+0x12b/0x220
 netdev_info+0x64/0x80
 ? bond_3ad_set_carrier+0xe9/0x180
 bond_select_active_slave+0x1fc/0x310
 bond_mii_monitor+0x709/0x9b0
 process_one_work+0x221/0x5e0
 worker_thread+0x4f/0x3b0
 kthread+0x100/0x140
 ? process_one_work+0x5e0/0x5e0
 ? kthread_delayed_work_timer_fn+0x90/0x90
 ret_from_fork+0x24/0x30

We're also doing rcu dereferences a layer up in netpoll_send_skb_on_dev
before we call down into netpoll_poll_dev, so just take the lock there.

Suggested-by: Cong Wang 
Signed-off-by: Dave Jones 

diff --git a/net/core/netpoll.c b/net/core/netpoll.c
index 3219a2932463..692367d7c280 100644
--- a/net/core/netpoll.c
+++ b/net/core/netpoll.c
@@ -330,6 +330,7 @@ void netpoll_send_skb_on_dev(struct netpoll *np, struct 
sk_buff *skb,
/* It is up to the caller to keep npinfo alive. */
struct netpoll_info *npinfo;
 
+   rcu_read_lock_bh();
lockdep_assert_irqs_disabled();
 
npinfo = rcu_dereference_bh(np->dev->npinfo);
@@ -374,6 +375,7 @@ void netpoll_send_skb_on_dev(struct netpoll *np, struct 
sk_buff *skb,
skb_queue_tail(&npinfo->txq, skb);
schedule_delayed_work(&npinfo->tx_work,0);
}
+   rcu_read_unlock_bh();
 }
 EXPORT_SYMBOL(netpoll_send_skb_on_dev);