macvtap bug: using smp_processor_id() in preemptible code

macvtap bug: using smp_processor_id() in preemptible code

[Thomas Huth]

 Hi,

I am using macvtap (via KVM/virsh) on a s390 box. With the latest
kernel source from linux-next master branch, I suddenly get the
following error messages in the dmesg output:

BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45891/45892
caller is macvtap_do_read+0x45c/0x600 [macvtap]
CPU: 1 PID: 45892 Comm: vhost-45891 Not tainted 3.11.0-bisecttest #13
       000000010cab3a00 000000010cab3a10 0000000000000002 0000000000000000 
       000000010cab3aa0 000000010cab3a18 000000010cab3a18 00000000001127b4 
       0000000000000000 0000000000000001 0000000000000000 000000010000000b 
       0000000000000060 000003fe00000008 0000000000000000 000000010cab3a70 
       00000000006ea2f0 00000000001127b4 000000010cab3a00 000000010cab3a50 
Call Trace:
([<00000000001126ee>] show_trace+0x126/0x144)
 [<00000000001127d2>] show_stack+0xc6/0xd4
 [<000000000068bcec>] dump_stack+0x74/0xd8
 [<0000000000481066>] debug_smp_processor_id+0xf6/0x114
 [<000003ff802e9a18>] macvtap_do_read+0x45c/0x600 [macvtap]
 [<000003ff802e9c1c>] macvtap_recvmsg+0x60/0x88 [macvtap]
 [<000003ff80318c5e>] handle_rx+0x5b2/0x800 [vhost_net]
 [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
 [<000000000015f3ac>] kthread+0xd8/0xe4
 [<00000000006934a6>] kernel_thread_starter+0x6/0xc
 [<00000000006934a0>] kernel_thread_starter+0x0/0xc
2 locks held by vhost-45891/45892:
 #0:  (&vq->mutex){+.+...}, at: [<000003ff80318718>] handle_rx+0x6c/0x800 [vhost_net]
 #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802e98fe>] macvtap_do_read+0x342/0x600 [macvtap]

Apart from these "annoying" error messages (they are repeated
continually while the KVM guest is running / macvtap is in use),
everything still seems to work fine, though.

Since everything was still working fine in v3.10, I did some bisecting
and it seems like this commit introduced this problem:

  commit: ac4e4af1e59e16a018527ffa58d9d3f30bb96ca9
  Subject: macvtap: Consistently use rcu functions

I am not sure how to proceed here, this is my first bug report in this
area, so advice is welcome...

 Regards,
  Thomas Huth

Re: macvtap bug: using smp_processor_id() in preemptible code

[Eric Dumazet]

On Wed, 2013-08-07 at 16:43 +0200, Thomas Huth wrote:
> Hi,
> 
> I am using macvtap (via KVM/virsh) on a s390 box. With the latest
> kernel source from linux-next master branch, I suddenly get the
> following error messages in the dmesg output:
> 
> BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45891/45892
> caller is macvtap_do_read+0x45c/0x600 [macvtap]
> CPU: 1 PID: 45892 Comm: vhost-45891 Not tainted 3.11.0-bisecttest #13
>        000000010cab3a00 000000010cab3a10 0000000000000002 0000000000000000 
>        000000010cab3aa0 000000010cab3a18 000000010cab3a18 00000000001127b4 
>        0000000000000000 0000000000000001 0000000000000000 000000010000000b 
>        0000000000000060 000003fe00000008 0000000000000000 000000010cab3a70 
>        00000000006ea2f0 00000000001127b4 000000010cab3a00 000000010cab3a50 
> Call Trace:
> ([<00000000001126ee>] show_trace+0x126/0x144)
>  [<00000000001127d2>] show_stack+0xc6/0xd4
>  [<000000000068bcec>] dump_stack+0x74/0xd8
>  [<0000000000481066>] debug_smp_processor_id+0xf6/0x114
>  [<000003ff802e9a18>] macvtap_do_read+0x45c/0x600 [macvtap]
>  [<000003ff802e9c1c>] macvtap_recvmsg+0x60/0x88 [macvtap]
>  [<000003ff80318c5e>] handle_rx+0x5b2/0x800 [vhost_net]
>  [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
>  [<000000000015f3ac>] kthread+0xd8/0xe4
>  [<00000000006934a6>] kernel_thread_starter+0x6/0xc
>  [<00000000006934a0>] kernel_thread_starter+0x0/0xc
> 2 locks held by vhost-45891/45892:
>  #0:  (&vq->mutex){+.+...}, at: [<000003ff80318718>] handle_rx+0x6c/0x800 [vhost_net]
>  #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802e98fe>] macvtap_do_read+0x342/0x600 [macvtap]
> 
> Apart from these "annoying" error messages (they are repeated
> continually while the KVM guest is running / macvtap is in use),
> everything still seems to work fine, though.
> 
> Since everything was still working fine in v3.10, I did some bisecting
> and it seems like this commit introduced this problem:
> 
>   commit: ac4e4af1e59e16a018527ffa58d9d3f30bb96ca9
>   Subject: macvtap: Consistently use rcu functions
> 
> I am not sure how to proceed here, this is my first bug report in this
> area, so advice is welcome...

Please try following fix :

diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
index a98fb0e..1c7aab4 100644
--- a/drivers/net/macvtap.c
+++ b/drivers/net/macvtap.c
@@ -912,8 +912,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
 done:
 	rcu_read_lock();
 	vlan = rcu_dereference(q->vlan);
-	if (vlan)
+	if (vlan) {
+		preempt_disable();
 		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
+		preempt_enable();
+	}
 	rcu_read_unlock();
 
 	return ret ? ret : copied;

Re: macvtap bug: using smp_processor_id() in preemptible code

[Thomas Huth]

 Hi,

Am Wed, 07 Aug 2013 08:26:51 -0700
schrieb Eric Dumazet <eric.dumazet@gmail.com>:

> On Wed, 2013-08-07 at 16:43 +0200, Thomas Huth wrote:
> > 
> > I am using macvtap (via KVM/virsh) on a s390 box. With the latest
> > kernel source from linux-next master branch, I suddenly get the
> > following error messages in the dmesg output:
> > 
> > BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45891/45892
> > caller is macvtap_do_read+0x45c/0x600 [macvtap]
> > CPU: 1 PID: 45892 Comm: vhost-45891 Not tainted 3.11.0-bisecttest #13
> >        000000010cab3a00 000000010cab3a10 0000000000000002 0000000000000000 
> >        000000010cab3aa0 000000010cab3a18 000000010cab3a18 00000000001127b4 
> >        0000000000000000 0000000000000001 0000000000000000 000000010000000b 
> >        0000000000000060 000003fe00000008 0000000000000000 000000010cab3a70 
> >        00000000006ea2f0 00000000001127b4 000000010cab3a00 000000010cab3a50 
> > Call Trace:
> > ([<00000000001126ee>] show_trace+0x126/0x144)
> >  [<00000000001127d2>] show_stack+0xc6/0xd4
> >  [<000000000068bcec>] dump_stack+0x74/0xd8
> >  [<0000000000481066>] debug_smp_processor_id+0xf6/0x114
> >  [<000003ff802e9a18>] macvtap_do_read+0x45c/0x600 [macvtap]
> >  [<000003ff802e9c1c>] macvtap_recvmsg+0x60/0x88 [macvtap]
> >  [<000003ff80318c5e>] handle_rx+0x5b2/0x800 [vhost_net]
> >  [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
> >  [<000000000015f3ac>] kthread+0xd8/0xe4
> >  [<00000000006934a6>] kernel_thread_starter+0x6/0xc
> >  [<00000000006934a0>] kernel_thread_starter+0x0/0xc
> > 2 locks held by vhost-45891/45892:
> >  #0:  (&vq->mutex){+.+...}, at: [<000003ff80318718>] handle_rx+0x6c/0x800 [vhost_net]
> >  #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802e98fe>] macvtap_do_read+0x342/0x600 [macvtap]
> > 
> > Apart from these "annoying" error messages (they are repeated
> > continually while the KVM guest is running / macvtap is in use),
> > everything still seems to work fine, though.
> > 
> > Since everything was still working fine in v3.10, I did some bisecting
> > and it seems like this commit introduced this problem:
> > 
> >   commit: ac4e4af1e59e16a018527ffa58d9d3f30bb96ca9
> >   Subject: macvtap: Consistently use rcu functions
> > 
> > I am not sure how to proceed here, this is my first bug report in this
> > area, so advice is welcome...
> 
> Please try following fix :
> 
> diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
> index a98fb0e..1c7aab4 100644
> --- a/drivers/net/macvtap.c
> +++ b/drivers/net/macvtap.c
> @@ -912,8 +912,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
>  done:
>  	rcu_read_lock();
>  	vlan = rcu_dereference(q->vlan);
> -	if (vlan)
> +	if (vlan) {
> +		preempt_disable();
>  		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
> +		preempt_enable();
> +	}
>  	rcu_read_unlock();
> 
>  	return ret ? ret : copied;

Thank you very much for your fast reply and the fix, it indeed fixes
the messages about macvtap_do_read!
However, I now noticed that there are more messages, which I just did
not see before because my dmesg output was already flooded with the
messages about macvtap_do_read. The other messages are all about
macvlan_start_xmit:

BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45897/45898
caller is macvlan_start_xmit+0x10a/0x1b4 [macvlan]
CPU: 1 PID: 45898 Comm: vhost-45897 Not tainted 3.11.0-bisecttest #16
       00000001189b3960 00000001189b3970 0000000000000002 0000000000000000 
       00000001189b3a00 00000001189b3978 00000001189b3978 00000000001127b4 
       0000000000000000 0000000000000001 0000000000000000 000000000000000b 
       0000000000000060 000003fe00000008 0000000000000000 00000001189b39d0 
       00000000006ea2f0 00000000001127b4 00000001189b3960 00000001189b39b0 
Call Trace:
([<00000000001126ee>] show_trace+0x126/0x144)
 [<00000000001127d2>] show_stack+0xc6/0xd4
 [<000000000068bdb8>] dump_stack+0x74/0xd4
 [<0000000000481132>] debug_smp_processor_id+0xf6/0x114
 [<000003ff802b72ca>] macvlan_start_xmit+0x10a/0x1b4 [macvlan]
 [<000003ff802ea69a>] macvtap_get_user+0x982/0xbc4 [macvtap]
 [<000003ff802ea92a>] macvtap_sendmsg+0x4e/0x60 [macvtap]
 [<000003ff8031947c>] handle_tx+0x494/0x5ec [vhost_net]
 [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
 [<000000000015f3ac>] kthread+0xd8/0xe4
 [<000000000069356e>] kernel_thread_starter+0x6/0xc
 [<0000000000693568>] kernel_thread_starter+0x0/0xc
2 locks held by vhost-45897/45898:
 #0:  (&vq->mutex){+.+.+.}, at: [<000003ff8031903c>] handle_tx+0x54/0x5ec [vhost_net]
 #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802ea53c>] macvtap_get_user+0x824/0xbc4 [macvtap]

Do you also have got an idea how to silence these messages?

 Thomas

Re: macvtap bug: using smp_processor_id() in preemptible code

[Eric Dumazet]

On Thu, 2013-08-08 at 10:25 +0200, Thomas Huth wrote:
> Hi,

> Thank you very much for your fast reply and the fix, it indeed fixes
> the messages about macvtap_do_read!
> However, I now noticed that there are more messages, which I just did
> not see before because my dmesg output was already flooded with the
> messages about macvtap_do_read. The other messages are all about
> macvlan_start_xmit:
> 
> BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45897/45898
> caller is macvlan_start_xmit+0x10a/0x1b4 [macvlan]
> CPU: 1 PID: 45898 Comm: vhost-45897 Not tainted 3.11.0-bisecttest #16
>        00000001189b3960 00000001189b3970 0000000000000002 0000000000000000 
>        00000001189b3a00 00000001189b3978 00000001189b3978 00000000001127b4 
>        0000000000000000 0000000000000001 0000000000000000 000000000000000b 
>        0000000000000060 000003fe00000008 0000000000000000 00000001189b39d0 
>        00000000006ea2f0 00000000001127b4 00000001189b3960 00000001189b39b0 
> Call Trace:
> ([<00000000001126ee>] show_trace+0x126/0x144)
>  [<00000000001127d2>] show_stack+0xc6/0xd4
>  [<000000000068bdb8>] dump_stack+0x74/0xd4
>  [<0000000000481132>] debug_smp_processor_id+0xf6/0x114
>  [<000003ff802b72ca>] macvlan_start_xmit+0x10a/0x1b4 [macvlan]
>  [<000003ff802ea69a>] macvtap_get_user+0x982/0xbc4 [macvtap]
>  [<000003ff802ea92a>] macvtap_sendmsg+0x4e/0x60 [macvtap]
>  [<000003ff8031947c>] handle_tx+0x494/0x5ec [vhost_net]
>  [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
>  [<000000000015f3ac>] kthread+0xd8/0xe4
>  [<000000000069356e>] kernel_thread_starter+0x6/0xc
>  [<0000000000693568>] kernel_thread_starter+0x0/0xc
> 2 locks held by vhost-45897/45898:
>  #0:  (&vq->mutex){+.+.+.}, at: [<000003ff8031903c>] handle_tx+0x54/0x5ec [vhost_net]
>  #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802ea53c>] macvtap_get_user+0x824/0xbc4 [macvtap]
> 
> Do you also have got an idea how to silence these messages?

Sure, please try following cumulative patch, thanks !

diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
index a98fb0e..b51db2a 100644
--- a/drivers/net/macvtap.c
+++ b/drivers/net/macvtap.c
@@ -818,10 +818,13 @@ static ssize_t macvtap_get_user(struct macvtap_queue *q, struct msghdr *m,
 		skb_shinfo(skb)->tx_flags |= SKBTX_DEV_ZEROCOPY;
 		skb_shinfo(skb)->tx_flags |= SKBTX_SHARED_FRAG;
 	}
-	if (vlan)
+	if (vlan) {
+		local_bh_disable();
 		macvlan_start_xmit(skb, vlan->dev);
-	else
+		local_bh_enable();
+	} else {
 		kfree_skb(skb);
+	}
 	rcu_read_unlock();
 
 	return total_len;
@@ -912,8 +915,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
 done:
 	rcu_read_lock();
 	vlan = rcu_dereference(q->vlan);
-	if (vlan)
+	if (vlan) {
+		preempt_disable();
 		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
+		preempt_enable();
+	}
 	rcu_read_unlock();
 
 	return ret ? ret : copied;

Re: macvtap bug: using smp_processor_id() in preemptible code

[Thomas Huth]

Am Thu, 08 Aug 2013 06:21:12 -0700
schrieb Eric Dumazet <eric.dumazet@gmail.com>:

> On Thu, 2013-08-08 at 10:25 +0200, Thomas Huth wrote:
> 
> > Thank you very much for your fast reply and the fix, it indeed fixes
> > the messages about macvtap_do_read!
> > However, I now noticed that there are more messages, which I just did
> > not see before because my dmesg output was already flooded with the
> > messages about macvtap_do_read. The other messages are all about
> > macvlan_start_xmit:
> > 
> > BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45897/45898
> > caller is macvlan_start_xmit+0x10a/0x1b4 [macvlan]
> > CPU: 1 PID: 45898 Comm: vhost-45897 Not tainted 3.11.0-bisecttest #16
> >        00000001189b3960 00000001189b3970 0000000000000002 0000000000000000 
> >        00000001189b3a00 00000001189b3978 00000001189b3978 00000000001127b4 
> >        0000000000000000 0000000000000001 0000000000000000 000000000000000b 
> >        0000000000000060 000003fe00000008 0000000000000000 00000001189b39d0 
> >        00000000006ea2f0 00000000001127b4 00000001189b3960 00000001189b39b0 
> > Call Trace:
> > ([<00000000001126ee>] show_trace+0x126/0x144)
> >  [<00000000001127d2>] show_stack+0xc6/0xd4
> >  [<000000000068bdb8>] dump_stack+0x74/0xd4
> >  [<0000000000481132>] debug_smp_processor_id+0xf6/0x114
> >  [<000003ff802b72ca>] macvlan_start_xmit+0x10a/0x1b4 [macvlan]
> >  [<000003ff802ea69a>] macvtap_get_user+0x982/0xbc4 [macvtap]
> >  [<000003ff802ea92a>] macvtap_sendmsg+0x4e/0x60 [macvtap]
> >  [<000003ff8031947c>] handle_tx+0x494/0x5ec [vhost_net]
> >  [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
> >  [<000000000015f3ac>] kthread+0xd8/0xe4
> >  [<000000000069356e>] kernel_thread_starter+0x6/0xc
> >  [<0000000000693568>] kernel_thread_starter+0x0/0xc
> > 2 locks held by vhost-45897/45898:
> >  #0:  (&vq->mutex){+.+.+.}, at: [<000003ff8031903c>] handle_tx+0x54/0x5ec [vhost_net]
> >  #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802ea53c>] macvtap_get_user+0x824/0xbc4 [macvtap]
> > 
> > Do you also have got an idea how to silence these messages?
> 
> Sure, please try following cumulative patch, thanks !
> 
> diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
> index a98fb0e..b51db2a 100644
> --- a/drivers/net/macvtap.c
> +++ b/drivers/net/macvtap.c
> @@ -818,10 +818,13 @@ static ssize_t macvtap_get_user(struct macvtap_queue *q, struct msghdr *m,
>  		skb_shinfo(skb)->tx_flags |= SKBTX_DEV_ZEROCOPY;
>  		skb_shinfo(skb)->tx_flags |= SKBTX_SHARED_FRAG;
>  	}
> -	if (vlan)
> +	if (vlan) {
> +		local_bh_disable();
>  		macvlan_start_xmit(skb, vlan->dev);
> -	else
> +		local_bh_enable();
> +	} else {
>  		kfree_skb(skb);
> +	}
>  	rcu_read_unlock();
> 
>  	return total_len;
> @@ -912,8 +915,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
>  done:
>  	rcu_read_lock();
>  	vlan = rcu_dereference(q->vlan);
> -	if (vlan)
> +	if (vlan) {
> +		preempt_disable();
>  		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
> +		preempt_enable();
> +	}
>  	rcu_read_unlock();
> 
>  	return ret ? ret : copied;

This patch now silences all error messages! Great, thank you very much!
If you submit this patch, you can add my
 Tested-by: Thomas Huth <thuth@linux.vnet.ibm.com>
if you like.

 Thomas

Re: macvtap bug: using smp_processor_id() in preemptible code

[Eric Dumazet]

On Thu, 2013-08-08 at 15:56 +0200, Thomas Huth wrote:

> This patch now silences all error messages! Great, thank you very much!
> If you submit this patch, you can add my
>  Tested-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> if you like.

Sure, I'll send a proper/official patch asap, thanks !

[PATCH] macvtap: fix two races

[Eric Dumazet]

From: Eric Dumazet <edumazet@google.com>

Since commit ac4e4af1e59e1 ("macvtap: Consistently use rcu functions"),
Thomas gets two different warnings :

BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45891/45892
caller is macvtap_do_read+0x45c/0x600 [macvtap]
CPU: 1 PID: 45892 Comm: vhost-45891 Not tainted 3.11.0-bisecttest #13
Call Trace:
([<00000000001126ee>] show_trace+0x126/0x144)
 [<00000000001127d2>] show_stack+0xc6/0xd4
 [<000000000068bcec>] dump_stack+0x74/0xd8
 [<0000000000481066>] debug_smp_processor_id+0xf6/0x114
 [<000003ff802e9a18>] macvtap_do_read+0x45c/0x600 [macvtap]
 [<000003ff802e9c1c>] macvtap_recvmsg+0x60/0x88 [macvtap]
 [<000003ff80318c5e>] handle_rx+0x5b2/0x800 [vhost_net]
 [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
 [<000000000015f3ac>] kthread+0xd8/0xe4
 [<00000000006934a6>] kernel_thread_starter+0x6/0xc
 [<00000000006934a0>] kernel_thread_starter+0x0/0xc

And

BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45897/45898
caller is macvlan_start_xmit+0x10a/0x1b4 [macvlan]
CPU: 1 PID: 45898 Comm: vhost-45897 Not tainted 3.11.0-bisecttest #16
Call Trace:
([<00000000001126ee>] show_trace+0x126/0x144)
 [<00000000001127d2>] show_stack+0xc6/0xd4
 [<000000000068bdb8>] dump_stack+0x74/0xd4
 [<0000000000481132>] debug_smp_processor_id+0xf6/0x114
 [<000003ff802b72ca>] macvlan_start_xmit+0x10a/0x1b4 [macvlan]
 [<000003ff802ea69a>] macvtap_get_user+0x982/0xbc4 [macvtap]
 [<000003ff802ea92a>] macvtap_sendmsg+0x4e/0x60 [macvtap]
 [<000003ff8031947c>] handle_tx+0x494/0x5ec [vhost_net]
 [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
 [<000000000015f3ac>] kthread+0xd8/0xe4
 [<000000000069356e>] kernel_thread_starter+0x6/0xc
 [<0000000000693568>] kernel_thread_starter+0x0/0xc
2 locks held by vhost-45897/45898:
 #0:  (&vq->mutex){+.+.+.}, at: [<000003ff8031903c>] handle_tx+0x54/0x5ec [vhost_net]
 #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802ea53c>] macvtap_get_user+0x824/0xbc4 [macvtap]


In the first case, macvtap_put_user() calls macvlan_count_rx()
in a preempt-able context, and this is not allowed.

In the second case, macvtap_get_user() calls
macvlan_start_xmit() with BH enabled, and this is not allowed.
 
Reported-by: Thomas Huth <thuth@linux.vnet.ibm.com>
Bisected-by: Thomas Huth <thuth@linux.vnet.ibm.com>
Signed-off-by: Eric Dumazet <edumazet@google.com>
Tested-by: Thomas Huth <thuth@linux.vnet.ibm.com>
Cc: Vlad Yasevich <vyasevic@redhat.com>
---
 drivers/net/macvtap.c |   12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
index a98fb0e..b51db2a 100644
--- a/drivers/net/macvtap.c
+++ b/drivers/net/macvtap.c
@@ -818,10 +818,13 @@ static ssize_t macvtap_get_user(struct macvtap_queue *q, struct msghdr *m,
 		skb_shinfo(skb)->tx_flags |= SKBTX_DEV_ZEROCOPY;
 		skb_shinfo(skb)->tx_flags |= SKBTX_SHARED_FRAG;
 	}
-	if (vlan)
+	if (vlan) {
+		local_bh_disable();
 		macvlan_start_xmit(skb, vlan->dev);
-	else
+		local_bh_enable();
+	} else {
 		kfree_skb(skb);
+	}
 	rcu_read_unlock();
 
 	return total_len;
@@ -912,8 +915,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
 done:
 	rcu_read_lock();
 	vlan = rcu_dereference(q->vlan);
-	if (vlan)
+	if (vlan) {
+		preempt_disable();
 		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
+		preempt_enable();
+	}
 	rcu_read_unlock();
 
 	return ret ? ret : copied;

Re: [PATCH] macvtap: fix two races

[Vlad Yasevich]

On 08/08/2013 11:06 AM, Eric Dumazet wrote:
> From: Eric Dumazet <edumazet@google.com>
>
> Since commit ac4e4af1e59e1 ("macvtap: Consistently use rcu functions"),
> Thomas gets two different warnings :
>
> BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45891/45892
> caller is macvtap_do_read+0x45c/0x600 [macvtap]
> CPU: 1 PID: 45892 Comm: vhost-45891 Not tainted 3.11.0-bisecttest #13
> Call Trace:
> ([<00000000001126ee>] show_trace+0x126/0x144)
>   [<00000000001127d2>] show_stack+0xc6/0xd4
>   [<000000000068bcec>] dump_stack+0x74/0xd8
>   [<0000000000481066>] debug_smp_processor_id+0xf6/0x114
>   [<000003ff802e9a18>] macvtap_do_read+0x45c/0x600 [macvtap]
>   [<000003ff802e9c1c>] macvtap_recvmsg+0x60/0x88 [macvtap]
>   [<000003ff80318c5e>] handle_rx+0x5b2/0x800 [vhost_net]
>   [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
>   [<000000000015f3ac>] kthread+0xd8/0xe4
>   [<00000000006934a6>] kernel_thread_starter+0x6/0xc
>   [<00000000006934a0>] kernel_thread_starter+0x0/0xc
>
> And
>
> BUG: using smp_processor_id() in preemptible [00000000] code: vhost-45897/45898
> caller is macvlan_start_xmit+0x10a/0x1b4 [macvlan]
> CPU: 1 PID: 45898 Comm: vhost-45897 Not tainted 3.11.0-bisecttest #16
> Call Trace:
> ([<00000000001126ee>] show_trace+0x126/0x144)
>   [<00000000001127d2>] show_stack+0xc6/0xd4
>   [<000000000068bdb8>] dump_stack+0x74/0xd4
>   [<0000000000481132>] debug_smp_processor_id+0xf6/0x114
>   [<000003ff802b72ca>] macvlan_start_xmit+0x10a/0x1b4 [macvlan]
>   [<000003ff802ea69a>] macvtap_get_user+0x982/0xbc4 [macvtap]
>   [<000003ff802ea92a>] macvtap_sendmsg+0x4e/0x60 [macvtap]
>   [<000003ff8031947c>] handle_tx+0x494/0x5ec [vhost_net]
>   [<000003ff8028f77c>] vhost_worker+0x15c/0x1c4 [vhost]
>   [<000000000015f3ac>] kthread+0xd8/0xe4
>   [<000000000069356e>] kernel_thread_starter+0x6/0xc
>   [<0000000000693568>] kernel_thread_starter+0x0/0xc
> 2 locks held by vhost-45897/45898:
>   #0:  (&vq->mutex){+.+.+.}, at: [<000003ff8031903c>] handle_tx+0x54/0x5ec [vhost_net]
>   #1:  (rcu_read_lock){.+.+..}, at: [<000003ff802ea53c>] macvtap_get_user+0x824/0xbc4 [macvtap]
>
>
> In the first case, macvtap_put_user() calls macvlan_count_rx()
> in a preempt-able context, and this is not allowed.
>
> In the second case, macvtap_get_user() calls
> macvlan_start_xmit() with BH enabled, and this is not allowed.
>
> Reported-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Bisected-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Tested-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Cc: Vlad Yasevich <vyasevic@redhat.com>
> ---
>   drivers/net/macvtap.c |   12 +++++++++---
>   1 file changed, 9 insertions(+), 3 deletions(-)
>
> diff --git a/drivers/net/macvtap.c b/drivers/net/macvtap.c
> index a98fb0e..b51db2a 100644
> --- a/drivers/net/macvtap.c
> +++ b/drivers/net/macvtap.c
> @@ -818,10 +818,13 @@ static ssize_t macvtap_get_user(struct macvtap_queue *q, struct msghdr *m,
>   		skb_shinfo(skb)->tx_flags |= SKBTX_DEV_ZEROCOPY;
>   		skb_shinfo(skb)->tx_flags |= SKBTX_SHARED_FRAG;
>   	}
> -	if (vlan)
> +	if (vlan) {
> +		local_bh_disable();
>   		macvlan_start_xmit(skb, vlan->dev);
> -	else
> +		local_bh_enable();
> +	} else {
>   		kfree_skb(skb);
> +	}
>   	rcu_read_unlock();
>
>   	return total_len;
> @@ -912,8 +915,11 @@ static ssize_t macvtap_put_user(struct macvtap_queue *q,
>   done:
>   	rcu_read_lock();
>   	vlan = rcu_dereference(q->vlan);
> -	if (vlan)
> +	if (vlan) {
> +		preempt_disable();
>   		macvlan_count_rx(vlan, copied - vnet_hdr_len, ret == 0, 0);
> +		preempt_enable();
> +	}

I was looking at this a bit more and I think this call to 
macvlan_count_rx() is double counting the packets.

In macvlan_handle_frame(), we call macvlan_count_rx() after we call
vlan->receive().  For macvtap, receive() function is essentially 
macvtap_forward() which just tacks the data onto the queue.

Then, the above code counts the data again as we pull it off the queue
socket queue to give to the user.

-vlad



>   	rcu_read_unlock();
>
>   	return ret ? ret : copied;
>
>

Re: [PATCH] macvtap: fix two races

[Eric Dumazet]

On Fri, 2013-08-09 at 13:16 -0400, Vlad Yasevich wrote:

> I was looking at this a bit more and I think this call to 
> macvlan_count_rx() is double counting the packets.
> 
> In macvlan_handle_frame(), we call macvlan_count_rx() after we call
> vlan->receive().  For macvtap, receive() function is essentially 
> macvtap_forward() which just tacks the data onto the queue.
> 
> Then, the above code counts the data again as we pull it off the queue
> socket queue to give to the user.

Hmm, it seems a different issue, and probably needs a patch on its own.

When was this problem added ?

Re: [PATCH] macvtap: fix two races

[Vlad Yasevich]

On 08/09/2013 01:41 PM, Eric Dumazet wrote:
> On Fri, 2013-08-09 at 13:16 -0400, Vlad Yasevich wrote:
>
>> I was looking at this a bit more and I think this call to
>> macvlan_count_rx() is double counting the packets.
>>
>> In macvlan_handle_frame(), we call macvlan_count_rx() after we call
>> vlan->receive().  For macvtap, receive() function is essentially
>> macvtap_forward() which just tacks the data onto the queue.
>>
>> Then, the above code counts the data again as we pull it off the queue
>> socket queue to give to the user.
>
> Hmm, it seems a different issue, and probably needs a patch on its own.
>
> When was this problem added ?
>
>

Looks like both macvlan and macvtap packet counting has been there since
the beginning...

-vlad

Re: [PATCH] macvtap: fix two races

[David Miller]

From: Eric Dumazet <eric.dumazet@gmail.com>
Date: Thu, 08 Aug 2013 08:06:14 -0700

> From: Eric Dumazet <edumazet@google.com>
> 
> Since commit ac4e4af1e59e1 ("macvtap: Consistently use rcu functions"),
> Thomas gets two different warnings :
 ...
> And
 ...
> In the first case, macvtap_put_user() calls macvlan_count_rx()
> in a preempt-able context, and this is not allowed.
> 
> In the second case, macvtap_get_user() calls
> macvlan_start_xmit() with BH enabled, and this is not allowed.
>  
> Reported-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Bisected-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Tested-by: Thomas Huth <thuth@linux.vnet.ibm.com>
> Cc: Vlad Yasevich <vyasevic@redhat.com>

Applied and queued up for -stable, thanks.