2012-05-25 20:26:06

by Jack Stone

[permalink] [raw]
Subject: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

Hi All,

The following warning keeps hitting me. I couldn't get the first one - it had already left dmesg hence the W taint.
The C taint is from r8712u from staging.

I've seen it with 3.4.0-076444-g07acfc2 (recent Linus tree) and 3.4.0-rc3-00089-gc6f5c93.

I am going to attempt to bisect it now.

[ 3896.037489] ------------[ cut here ]------------
[ 3896.037490] WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()
[ 3896.037491] Hardware name: System Product Name
[ 3896.037491] recvmsg bug 2: copied 3F1199D7 seq 3F1199D7 rcvnxt 3F119A71 fl 0
[ 3896.037511] Modules linked in: fuse ebtable_nat ebtables ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge rfcomm lockd 8021q garp stp llc bnep nf_conntrack_netbios_ns nf_conntrack_broadcast ip6t_REJECT nf_conntrack_ipv4 nf_conntrack_ipv6 nf_defrag_ipv6 nf_defrag_ipv4 xt_state nf_conntrack ip6table_filter ip6_tables vhost_net snd_hda_codec_hdmi macvtap macvlan tun snd_hda_codec_realtek virtio_net btusb bluetooth coretemp kvm_intel kvm snd_hda_intel r8712u(C) snd_hda_codec snd_hwdep e1000e joydev snd_seq snd_seq_device snd_pcm snd_timer snd sunrpc eeepc_wmi asus_wmi hid_logitech_dj sparse_keymap mxm_wmi soundcore iTCO_wdt rfkill snd_page_alloc wmi i2c_i801 pcspkr iTCO_vendor_support serio_raw binfmt_misc uinput microcode crc32c_intel ghash_clmulni_intel firewire_ohci firewire_core crc_itu_t [last unloaded: scsi_wait_scan]
[ 3896.037512] Pid: 3926, comm: spotify Tainted: G WC 3.4.0-07644-g07acfc2 #2
[ 3896.037513] Call Trace:
[ 3896.037514] [<ffffffff8106010f>] warn_slowpath_common+0x7f/0xc0
[ 3896.037515] [<ffffffff81060206>] warn_slowpath_fmt+0x46/0x50
[ 3896.037517] [<ffffffff8163f4c5>] ? tcp_recvmsg+0x35/0xc70
[ 3896.037518] [<ffffffff812c130f>] ? avc_has_perm_flags+0xef/0x230
[ 3896.037519] [<ffffffff812c125c>] ? avc_has_perm_flags+0x3c/0x230
[ 3896.037520] [<ffffffff8163ffab>] tcp_recvmsg+0xb1b/0xc70
[ 3896.037522] [<ffffffff8166a8c0>] ? inet_sendmsg+0x230/0x230
[ 3896.037523] [<ffffffff8166a9f7>] inet_recvmsg+0x137/0x250
[ 3896.037525] [<ffffffff815d7f58>] ? sock_update_classid+0x128/0x310
[ 3896.037526] [<ffffffff815cfe40>] do_sock_read+0xf0/0x110
[ 3896.037527] [<ffffffff815d0b8c>] sock_aio_read.part.5+0x4c/0x70
[ 3896.037528] [<ffffffff812c130f>] ? avc_has_perm_flags+0xef/0x230
[ 3896.037530] [<ffffffff815d0bb0>] ? sock_aio_read.part.5+0x70/0x70
[ 3896.037531] [<ffffffff815d0bdd>] sock_aio_read+0x2d/0x40
[ 3896.037532] [<ffffffff811bc2b3>] do_sync_readv_writev+0xd3/0x110
[ 3896.037534] [<ffffffff812beca6>] ? security_file_permission+0x96/0xb0
[ 3896.037535] [<ffffffff811bb9a1>] ? rw_verify_area+0x61/0x100
[ 3896.037537] [<ffffffff811bc584>] do_readv_writev+0xd4/0x1d0
[ 3896.037538] [<ffffffff811bdad8>] ? fget_light+0x48/0x4f0
[ 3896.037540] [<ffffffff811bdad8>] ? fget_light+0x48/0x4f0
[ 3896.037541] [<ffffffff811bc71c>] vfs_readv+0x3c/0x50
[ 3896.037543] [<ffffffff811bc77d>] sys_readv+0x4d/0xc0
[ 3896.037544] [<ffffffff8174c829>] system_call_fastpath+0x16/0x1b
[ 3896.037545] ---[ end trace 762b4689c56af7ab ]---

The relevant code from tcp.c is:

/* Next get a buffer. */

skb_queue_walk(&sk->sk_receive_queue, skb) {
/* Now that we have two receive queues this
* shouldn't happen.
*/
if (WARN(before(*seq, TCP_SKB_CB(skb)->seq),
"recvmsg bug: copied %X seq %X rcvnxt %X fl %X\n",
*seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt,
flags))
break;

offset = *seq - TCP_SKB_CB(skb)->seq;
if (tcp_hdr(skb)->syn)
offset--;
if (offset < skb->len)
goto found_ok_skb;
if (tcp_hdr(skb)->fin)
goto found_fin_ok;
This warn here -----> WARN(!(flags & MSG_PEEK),
"recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
*seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
}

Thanks,

Jack


2012-05-25 20:45:31

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Fri, 2012-05-25 at 21:25 +0100, Jack Stone wrote:
> Hi All,
>
> The following warning keeps hitting me. I couldn't get the first one - it had already left dmesg hence the W taint.
> The C taint is from r8712u from staging.
>
> I've seen it with 3.4.0-076444-g07acfc2 (recent Linus tree) and 3.4.0-rc3-00089-gc6f5c93.
>
> I am going to attempt to bisect it now.

No need, update your tree.


2012-05-25 20:55:39

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Fri, 2012-05-25 at 22:45 +0200, Eric Dumazet wrote:
> On Fri, 2012-05-25 at 21:25 +0100, Jack Stone wrote:
> > Hi All,
> >
> > The following warning keeps hitting me. I couldn't get the first one - it had already left dmesg hence the W taint.
> > The C taint is from r8712u from staging.
> >
> > I've seen it with 3.4.0-076444-g07acfc2 (recent Linus tree) and 3.4.0-rc3-00089-gc6f5c93.
> >
> > I am going to attempt to bisect it now.
>
> No need, update your tree.
>
>


http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=1ca7ee30630e1022dbcf1b51be20580815ffab73


2012-05-25 21:31:50

by Jack Stone

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On 05/25/2012 09:55 PM, Eric Dumazet wrote:
> On Fri, 2012-05-25 at 22:45 +0200, Eric Dumazet wrote:
>> No need, update your tree.
>
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=1ca7ee30630e1022dbcf1b51be20580815ffab73
>

Thank you. Rebuilding now.

Jack

2012-05-26 11:22:34

by Jack Stone

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On 05/25/2012 09:55 PM, Eric Dumazet wrote:
> On Fri, 2012-05-25 at 22:45 +0200, Eric Dumazet wrote:
>> On Fri, 2012-05-25 at 21:25 +0100, Jack Stone wrote:
>>> Hi All,
>>>
>>> The following warning keeps hitting me. I couldn't get the first one - it had already left dmesg hence the W taint.
>>> The C taint is from r8712u from staging.
>>>
>>> I've seen it with 3.4.0-076444-g07acfc2 (recent Linus tree) and 3.4.0-rc3-00089-gc6f5c93.
>>>
>>> I am going to attempt to bisect it now.
>>
>> No need, update your tree.
>>
>>
>
>
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=1ca7ee30630e1022dbcf1b51be20580815ffab73
>
>
>

I'm still getting this with da89fb1 which includes the above

Linux hover1 3.4.0-07797-gda89fb1 #4 SMP Fri May 25 22:23:14 BST 2012 x86_64 x86_64 x86_64 GNU/Linux

2012-05-27 13:59:51

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Sat, 2012-05-26 at 12:22 +0100, Jack Stone wrote:

> I'm still getting this with da89fb1 which includes the above
>
> Linux hover1 3.4.0-07797-gda89fb1 #4 SMP Fri May 25 22:23:14 BST 2012 x86_64 x86_64 x86_64 GNU/Linux

Thanks

Could you add following debugging patch ?

diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
index 3ba605f..b56c63c 100644
--- a/net/ipv4/tcp.c
+++ b/net/ipv4/tcp.c
@@ -1606,8 +1606,9 @@ int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
if (tcp_hdr(skb)->fin)
goto found_fin_ok;
WARN(!(flags & MSG_PEEK),
- "recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
- *seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
+ "recvmsg bug 2: copied %X seq %X end_seq %X rcvnxt %X fl %X offset %u len %u syn %d\n",
+ *seq, TCP_SKB_CB(skb)->seq, TCP_SKB_CB(skb)->end_seq,
+ tp->rcv_nxt, flags, offset, skb->len, tcp_hdr(skb)->syn);
}

/* Well, if we have backlog, try to process it now yet. */

2012-05-27 15:35:05

by Jack Stone

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On 05/27/2012 02:59 PM, Eric Dumazet wrote:
> On Sat, 2012-05-26 at 12:22 +0100, Jack Stone wrote:
>
>> I'm still getting this with da89fb1 which includes the above
>>
>> Linux hover1 3.4.0-07797-gda89fb1 #4 SMP Fri May 25 22:23:14 BST 2012 x86_64 x86_64 x86_64 GNU/Linux
>
> Thanks
>
> Could you add following debugging patch ?
>
> diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
> index 3ba605f..b56c63c 100644
> --- a/net/ipv4/tcp.c
> +++ b/net/ipv4/tcp.c
> @@ -1606,8 +1606,9 @@ int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
> if (tcp_hdr(skb)->fin)
> goto found_fin_ok;
> WARN(!(flags & MSG_PEEK),
> - "recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
> - *seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
> + "recvmsg bug 2: copied %X seq %X end_seq %X rcvnxt %X fl %X offset %u len %u syn %d\n",
> + *seq, TCP_SKB_CB(skb)->seq, TCP_SKB_CB(skb)->end_seq,
> + tp->rcv_nxt, flags, offset, skb->len, tcp_hdr(skb)->syn);
> }
>
> /* Well, if we have backlog, try to process it now yet. */
>
>

uname: Linux hover1 3.4.0-07822-g786f02b-dirty #1 SMP Sun May 27 15:23:39 BST 2012 x86_64 x86_64 x86_64 GNU/Linux

Here's the new output:


May 27 16:32:30 hover1 kernel: [ 1907.804613] ------------[ cut here ]------------
May 27 16:32:30 hover1 kernel: [ 1907.804622] WARNING: at net/ipv4/tcp.c:1611 tcp_recvmsg+0xb36/0xc90()
May 27 16:32:30 hover1 kernel: [ 1907.804624] Hardware name: System Product Name
May 27 16:32:30 hover1 kernel: [ 1907.804626] recvmsg bug 2: copied 8F322DEB seq 8F322DEB end_seq 8F322F2A rcvnxt 8F322F2A fl 0 offset 4294967295 len 319 syn 1
May 27 16:32:30 hover1 kernel: [ 1907.804665] Modules linked in: fuse ebtable_nat ebtables ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge rfcomm lockd 8021q garp stp llc bnep ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_netbios_ns nf_conntrack_broadcast ip6table_filter ip6_tables nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack snd_hda_codec_hdmi snd_hda_codec_realtek coretemp vhost_net macvtap macvlan tun virtio_net kvm_intel snd_hda_intel kvm snd_hda_codec btusb bluetooth snd_hwdep e1000e snd_seq eeepc_wmi asus_wmi sparse_keymap microcode r8712u(C) snd_seq_device rfkill snd_pcm joydev sunrpc snd_timer snd mxm_wmi hid_logitech_dj iTCO_wdt wmi iTCO_vendor_support i2c_i801 soundcore snd_page_alloc binfmt_misc serio_raw pcspkr uinput crc32c_intel ghash_clmulni_intel firewire_ohci firewire_core crc_itu_t [last unloaded: scsi_wait_scan]
May 27 16:32:30 hover1 kernel: [ 1907.804669] Pid: 2275, comm: thunderbird-bin Tainted: G C 3.4.0-07822-g786f02b-dirty #1
May 27 16:32:30 hover1 kernel: [ 1907.804670] Call Trace:
May 27 16:32:30 hover1 kernel: [ 1907.804674] [<ffffffff8106010f>] warn_slowpath_common+0x7f/0xc0
May 27 16:32:30 hover1 kernel: [ 1907.804676] [<ffffffff81060206>] warn_slowpath_fmt+0x46/0x50
May 27 16:32:30 hover1 kernel: [ 1907.804679] [<ffffffff8163f7f5>] ? tcp_recvmsg+0x35/0xc90
May 27 16:32:30 hover1 kernel: [ 1907.804681] [<ffffffff816402f6>] tcp_recvmsg+0xb36/0xc90
May 27 16:32:30 hover1 kernel: [ 1907.804685] [<ffffffff8166ac10>] ? inet_sendmsg+0x230/0x230
May 27 16:32:30 hover1 kernel: [ 1907.804687] [<ffffffff8166ad47>] inet_recvmsg+0x137/0x250
May 27 16:32:30 hover1 kernel: [ 1907.804691] [<ffffffff815d8288>] ? sock_update_classid+0x128/0x310
May 27 16:32:30 hover1 kernel: [ 1907.804693] [<ffffffff815d04ed>] sock_recvmsg+0x11d/0x140
May 27 16:32:30 hover1 kernel: [ 1907.804697] [<ffffffff811d85ff>] ? file_update_time+0xdf/0x140
May 27 16:32:30 hover1 kernel: [ 1907.804701] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
May 27 16:32:30 hover1 kernel: [ 1907.804703] [<ffffffff811bdd76>] ? fget_light+0x106/0x4f0
May 27 16:32:30 hover1 kernel: [ 1907.804705] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
May 27 16:32:30 hover1 kernel: [ 1907.804708] [<ffffffff815d3941>] sys_recvfrom+0xf1/0x170
May 27 16:32:30 hover1 kernel: [ 1907.804712] [<ffffffff810f6ddc>] ? __audit_syscall_entry+0xcc/0x310
May 27 16:32:30 hover1 kernel: [ 1907.804715] [<ffffffff8132dfce>] ? trace_hardirqs_on_thunk+0x3a/0x3f
May 27 16:32:30 hover1 kernel: [ 1907.804719] [<ffffffff8174cc69>] system_call_fastpath+0x16/0x1b
May 27 16:32:30 hover1 kernel: [ 1907.804720] ---[ end trace 4797381fbdf33b5d ]---

Thanks,

Jack

2012-05-27 17:36:08

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Sun, 2012-05-27 at 16:34 +0100, Jack Stone wrote:
> On 05/27/2012 02:59 PM, Eric Dumazet wrote:
> > On Sat, 2012-05-26 at 12:22 +0100, Jack Stone wrote:
> >
> >> I'm still getting this with da89fb1 which includes the above
> >>
> >> Linux hover1 3.4.0-07797-gda89fb1 #4 SMP Fri May 25 22:23:14 BST 2012 x86_64 x86_64 x86_64 GNU/Linux
> >
> > Thanks
> >
> > Could you add following debugging patch ?
> >
> > diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
> > index 3ba605f..b56c63c 100644
> > --- a/net/ipv4/tcp.c
> > +++ b/net/ipv4/tcp.c
> > @@ -1606,8 +1606,9 @@ int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
> > if (tcp_hdr(skb)->fin)
> > goto found_fin_ok;
> > WARN(!(flags & MSG_PEEK),
> > - "recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
> > - *seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
> > + "recvmsg bug 2: copied %X seq %X end_seq %X rcvnxt %X fl %X offset %u len %u syn %d\n",
> > + *seq, TCP_SKB_CB(skb)->seq, TCP_SKB_CB(skb)->end_seq,
> > + tp->rcv_nxt, flags, offset, skb->len, tcp_hdr(skb)->syn);
> > }
> >
> > /* Well, if we have backlog, try to process it now yet. */
> >
> >
>
> uname: Linux hover1 3.4.0-07822-g786f02b-dirty #1 SMP Sun May 27 15:23:39 BST 2012 x86_64 x86_64 x86_64 GNU/Linux
>
> Here's the new output:
>
>
> May 27 16:32:30 hover1 kernel: [ 1907.804613] ------------[ cut here ]------------
> May 27 16:32:30 hover1 kernel: [ 1907.804622] WARNING: at net/ipv4/tcp.c:1611 tcp_recvmsg+0xb36/0xc90()
> May 27 16:32:30 hover1 kernel: [ 1907.804624] Hardware name: System Product Name
> May 27 16:32:30 hover1 kernel: [ 1907.804626] recvmsg bug 2: copied 8F322DEB seq 8F322DEB end_seq 8F322F2A rcvnxt 8F322F2A fl 0 offset 4294967295 len 319 syn 1

So it seems we can queue in sk_receive_queue a packet with SYN flag set.

(A SYN or SYNACK packet contains DATA payload...)

The sequence number of such frames should be tweaked (seq++) instead of
games we do in fast path :

if (tcp_hdr(skb)->syn)
offset--;


Oh well this can wait linux-3.6, please test following patch in the
meantime.

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index b224eb8..34c8dcc 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c
@@ -4553,7 +4553,7 @@ static bool tcp_try_coalesce(struct sock *sk,

*fragstolen = false;

- if (tcp_hdr(from)->fin)
+ if (tcp_hdr(from)->fin || tcp_hdr(to)->syn)
return false;

/* Its possible this segment overlaps with prior segment in queue */

2012-05-27 19:13:47

by Jack Stone

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On 05/27/2012 06:35 PM, Eric Dumazet wrote:
> So it seems we can queue in sk_receive_queue a packet with SYN flag set.
>
> (A SYN or SYNACK packet contains DATA payload...)
>
> The sequence number of such frames should be tweaked (seq++) instead of
> games we do in fast path :
>
> if (tcp_hdr(skb)->syn)
> offset--;
>
>
> Oh well this can wait linux-3.6, please test following patch in the
> meantime.
>
> diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
> index b224eb8..34c8dcc 100644
> --- a/net/ipv4/tcp_input.c
> +++ b/net/ipv4/tcp_input.c
> @@ -4553,7 +4553,7 @@ static bool tcp_try_coalesce(struct sock *sk,
>
> *fragstolen = false;
>
> - if (tcp_hdr(from)->fin)
> + if (tcp_hdr(from)->fin || tcp_hdr(to)->syn)
> return false;
>
> /* Its possible this segment overlaps with prior segment in queue */
>
>

Still seems to fire with the above applied, it also sets of the warn just above it...

Could it be something to do with my staging network driver?

[ 2605.769938] ------------[ cut here ]------------
[ 2605.769942] WARNING: at net/ipv4/tcp.c:1611 tcp_recvmsg+0xb36/0xc90()
[ 2605.769943] Hardware name: System Product Name
[ 2605.769944] recvmsg bug 2: copied 84322A4D seq 84322A4D end_seq 84322A86 rcvnxt 843233B3 fl 0 offset 4294967295 len 57 syn 1
[ 2605.769982] Modules linked in: fuse ebtable_nat ebtables ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge lockd rfcomm 8021q garp stp llc bnep ip6t_REJECT nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ip6table_filter ip6_tables snd_hda_codec_hdmi snd_hda_codec_realtek vhost_net macvtap macvlan tun coretemp virtio_net kvm_intel kvm btusb bluetooth snd_hda_intel snd_hda_codec snd_hwdep snd_seq sunrpc r8712u(C) snd_seq_device snd_pcm snd_timer eeepc_wmi asus_wmi sparse_keymap e1000e mxm_wmi snd soundcore joydev wmi rfkill i2c_i801 snd_page_alloc iTCO_wdt serio_raw hid_logitech_dj pcspkr iTCO_vendor_support binfmt_misc microcode uinput crc32c_intel ghash_clmulni_intel firewire_ohci firewire_core crc_itu_t [last unloaded: scsi_wait_scan]
[ 2605.769985] Pid: 3305, comm: firefox Tainted: G WC 3.4.0-07822-g786f02b-dirty #2
[ 2605.769986] Call Trace:
[ 2605.769988] [<ffffffff8106010f>] warn_slowpath_common+0x7f/0xc0
[ 2605.769990] [<ffffffff81060206>] warn_slowpath_fmt+0x46/0x50
[ 2605.769993] [<ffffffff8163f7f5>] ? tcp_recvmsg+0x35/0xc90
[ 2605.769996] [<ffffffff816402f6>] tcp_recvmsg+0xb36/0xc90
[ 2605.769998] [<ffffffff8166ac20>] ? inet_sendmsg+0x230/0x230
[ 2605.770001] [<ffffffff8166ad57>] inet_recvmsg+0x137/0x250
[ 2605.770004] [<ffffffff815d8288>] ? sock_update_classid+0x128/0x310
[ 2605.770006] [<ffffffff815d04ed>] sock_recvmsg+0x11d/0x140
[ 2605.770009] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
[ 2605.770012] [<ffffffff811d1920>] ? __pollwait+0xf0/0xf0
[ 2605.770014] [<ffffffff811bdd76>] ? fget_light+0x106/0x4f0
[ 2605.770017] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
[ 2605.770020] [<ffffffff815d3941>] sys_recvfrom+0xf1/0x170
[ 2605.770022] [<ffffffff810f6ddc>] ? __audit_syscall_entry+0xcc/0x310
[ 2605.770025] [<ffffffff8132dfce>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 2605.770028] [<ffffffff8174cc69>] system_call_fastpath+0x16/0x1b
[ 2605.770029] ---[ end trace f86533e3bdc5b326 ]---
------------[ cut here ]------------
[ 2605.770032] WARNING: at net/ipv4/tcp.c:1598 tcp_recvmsg+0x409/0xc90()
[ 2605.770034] Hardware name: System Product Name
[ 2605.770082] recvmsg bug: copied 84322A4D seq 84322A86 rcvnxt 843233B3 fl 0
[ 2605.770119] Modules linked in: fuse ebtable_nat ebtables ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge lockd rfcomm 8021q garp stp llc bnep ip6t_REJECT nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ip6table_filter ip6_tables snd_hda_codec_hdmi snd_hda_codec_realtek vhost_net macvtap macvlan tun coretemp virtio_net kvm_intel kvm btusb bluetooth snd_hda_intel snd_hda_codec snd_hwdep snd_seq sunrpc r8712u(C) snd_seq_device snd_pcm snd_timer eeepc_wmi asus_wmi sparse_keymap e1000e mxm_wmi snd soundcore joydev wmi rfkill i2c_i801 snd_page_alloc iTCO_wdt serio_raw hid_logitech_dj pcspkr iTCO_vendor_support binfmt_misc microcode uinput crc32c_intel ghash_clmulni_intel firewire_ohci firewire_core crc_itu_t [last unloaded: scsi_wait_scan]
[ 2605.770122] Pid: 3305, comm: firefox Tainted: G WC 3.4.0-07822-g786f02b-dirty #2
[ 2605.770123] Call Trace:
[ 2605.770125] [<ffffffff8106010f>] warn_slowpath_common+0x7f/0xc0
[ 2605.770128] [<ffffffff81060206>] warn_slowpath_fmt+0x46/0x50
[ 2605.770130] [<ffffffff8163f7f5>] ? tcp_recvmsg+0x35/0xc90
[ 2605.770132] [<ffffffff8163fbc9>] tcp_recvmsg+0x409/0xc90
[ 2605.770135] [<ffffffff8166ac20>] ? inet_sendmsg+0x230/0x230
[ 2605.770138] [<ffffffff8166ad57>] inet_recvmsg+0x137/0x250
[ 2605.770140] [<ffffffff815d8288>] ? sock_update_classid+0x128/0x310
[ 2605.770143] [<ffffffff815d04ed>] sock_recvmsg+0x11d/0x140
[ 2605.770146] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
[ 2605.770148] [<ffffffff811d1920>] ? __pollwait+0xf0/0xf0
[ 2605.770150] [<ffffffff811bdd76>] ? fget_light+0x106/0x4f0
[ 2605.770152] [<ffffffff811bdcb8>] ? fget_light+0x48/0x4f0
[ 2605.770154] [<ffffffff815d3941>] sys_recvfrom+0xf1/0x170
[ 2605.770157] [<ffffffff810f6ddc>] ? __audit_syscall_entry+0xcc/0x310
[ 2605.770160] [<ffffffff8132dfce>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 2605.770163] [<ffffffff8174cc69>] system_call_fastpath+0x16/0x1b
[ 2605.770164] ---[ end trace f86533e3bdc5b327 ]---

Thanks,

Jack

2012-05-27 19:36:20

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Sun, 2012-05-27 at 20:13 +0100, Jack Stone wrote:
> On 05/27/2012 06:35 PM, Eric Dumazet wrote:
> > So it seems we can queue in sk_receive_queue a packet with SYN flag set.
> >
> > (A SYN or SYNACK packet contains DATA payload...)
> >
> > The sequence number of such frames should be tweaked (seq++) instead of
> > games we do in fast path :
> >
> > if (tcp_hdr(skb)->syn)
> > offset--;
> >
> >
> > Oh well this can wait linux-3.6, please test following patch in the
> > meantime.
> >
> > diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
> > index b224eb8..34c8dcc 100644
> > --- a/net/ipv4/tcp_input.c
> > +++ b/net/ipv4/tcp_input.c
> > @@ -4553,7 +4553,7 @@ static bool tcp_try_coalesce(struct sock *sk,
> >
> > *fragstolen = false;
> >
> > - if (tcp_hdr(from)->fin)
> > + if (tcp_hdr(from)->fin || tcp_hdr(to)->syn)
> > return false;
> >
> > /* Its possible this segment overlaps with prior segment in queue */
> >
> >
>
> Still seems to fire with the above applied, it also sets of the warn just above it...
>
> Could it be something to do with my staging network driver?


Yes it could be memory corruption.

(making tcp _think_ tcp_hdr(skb)->syn is set, while it was not at all.

Please replace debugging patch by following, because tcp flags are
copied elsewhere, so we can double check.

diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
index 3ba605f..22e4c9a 100644
--- a/net/ipv4/tcp.c
+++ b/net/ipv4/tcp.c
@@ -1606,8 +1606,10 @@ int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
if (tcp_hdr(skb)->fin)
goto found_fin_ok;
WARN(!(flags & MSG_PEEK),
- "recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
- *seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
+ "recvmsg bug 2: copied %X seq %X end_seq %X rcvnxt %X fl %X offset %u len %u syn %d tcp_flags %X\n",
+ *seq, TCP_SKB_CB(skb)->seq, TCP_SKB_CB(skb)->end_seq,
+ tp->rcv_nxt, flags, offset, skb->len, tcp_hdr(skb)->syn,
+ TCP_SKB_CB(skb)->tcp_flags);
}

/* Well, if we have backlog, try to process it now yet. */

2012-05-27 19:46:18

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Sun, 2012-05-27 at 21:36 +0200, Eric Dumazet wrote:
> pied elsewhere, so we can double check.
>
> diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
> index 3ba605f..22e4c9a 100644
> --- a/net/ipv4/tcp.c
> +++ b/net/ipv4/tcp.c
> @@ -1606,8 +1606,10 @@ int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
> if (tcp_hdr(skb)->fin)
> goto found_fin_ok;
> WARN(!(flags & MSG_PEEK),
> - "recvmsg bug 2: copied %X seq %X rcvnxt %X fl %X\n",
> - *seq, TCP_SKB_CB(skb)->seq, tp->rcv_nxt, flags);
> + "recvmsg bug 2: copied %X seq %X end_seq %X rcvnxt %X fl %X offset %u len %u syn %d tcp_flags %X\n",
> + *seq, TCP_SKB_CB(skb)->seq, TCP_SKB_CB(skb)->end_seq,
> + tp->rcv_nxt, flags, offset, skb->len, tcp_hdr(skb)->syn,
> + TCP_SKB_CB(skb)->tcp_flags);
> }
>
> /* Well, if we have backlog, try to process it now yet. */
>

Oh well, ignore this, as tcp_flags is only set in output path.


2012-05-28 00:25:36

by Eric Dumazet

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On Sun, 2012-05-27 at 20:13 +0100, Jack Stone wrote:

> Could it be something to do with my staging network driver?

drivers/staging/rtl8712/rtl8712_recv.c

line 1096

precvframe->u.hdr.pkt = skb_clone(pskb, GFP_ATOMIC);

This looks very wrong.
Make sure you never _never_ hit this path.


2012-05-28 08:34:10

by Jack Stone

[permalink] [raw]
Subject: Re: WARNING: at net/ipv4/tcp.c:1610 tcp_recvmsg+0xb1b/0xc70()

On 05/28/2012 01:25 AM, Eric Dumazet wrote:
> On Sun, 2012-05-27 at 20:13 +0100, Jack Stone wrote:
>
>> Could it be something to do with my staging network driver?
>
> drivers/staging/rtl8712/rtl8712_recv.c
>
> line 1096
>
> precvframe->u.hdr.pkt = skb_clone(pskb, GFP_ATOMIC);
>
> This looks very wrong.
> Make sure you never _never_ hit this path.
>

I've applied the following debugging patch. Thanks for the suggestion.

diff --git a/drivers/staging/rtl8712/rtl8712_recv.c b/drivers/staging/rtl8712/rtl8712_recv.c
index 8e82ce2..fed62f8 100644
--- a/drivers/staging/rtl8712/rtl8712_recv.c
+++ b/drivers/staging/rtl8712/rtl8712_recv.c
@@ -1082,23 +1082,16 @@ static int recvbuf2recvframe(struct _adapter *padapter, struct sk_buff *pskb)
* 4 is for skb->data 4 bytes alignment. */
alloc_sz += 6;
pkt_copy = netdev_alloc_skb(padapter->pnetdev, alloc_sz);
- if (pkt_copy) {
- pkt_copy->dev = padapter->pnetdev;
- precvframe->u.hdr.pkt = pkt_copy;
- skb_reserve(pkt_copy, 4 - ((addr_t)(pkt_copy->data)
- % 4));
- skb_reserve(pkt_copy, shift_sz);
- memcpy(pkt_copy->data, pbuf, tmp_len);
- precvframe->u.hdr.rx_head = precvframe->u.hdr.rx_data =
- precvframe->u.hdr.rx_tail = pkt_copy->data;
- precvframe->u.hdr.rx_end = pkt_copy->data + alloc_sz;
- } else {
- precvframe->u.hdr.pkt = skb_clone(pskb, GFP_ATOMIC);
- precvframe->u.hdr.rx_head = pbuf;
- precvframe->u.hdr.rx_data = pbuf;
- precvframe->u.hdr.rx_tail = pbuf;
- precvframe->u.hdr.rx_end = pbuf + alloc_sz;
- }
+ WARN_ON(!pkt_copy)
+ pkt_copy->dev = padapter->pnetdev;
+ precvframe->u.hdr.pkt = pkt_copy;
+ skb_reserve(pkt_copy, 4 - ((addr_t)(pkt_copy->data)
+ % 4));
+ skb_reserve(pkt_copy, shift_sz);
+ memcpy(pkt_copy->data, pbuf, tmp_len);
+ precvframe->u.hdr.rx_head = precvframe->u.hdr.rx_data =
+ precvframe->u.hdr.rx_tail = pkt_copy->data;
+ precvframe->u.hdr.rx_end = pkt_copy->data + alloc_sz;
recvframe_put(precvframe, tmp_len);
recvframe_pull(precvframe, drvinfo_sz + RXDESC_SIZE);
/* because the endian issue, driver avoid reference to the