Prev: QoS and/or fair queueing: Stateless NAT BUG
Next: Bluetooth: hidp: Add support for hidraw HIDIOCGFEATURE and HIDIOCSFEATURE
From: Eric Dumazet on 13 Jul 2010 12:00
Le mardi 13 juillet 2010 à 11:49 -0300, Felipe W Damasio a écrit :
> Hi Mr. Dumazet,
>
> 2010/7/13 Eric Dumazet <eric.dumazet(a)gmail.com>:
> > I currently have no fresh ideas. If you want this problem to be solved,
> > its important to setup in your lab a workload to trigger again and again
> > the bug, in order to provide us more crash information.
>
> Right. I've been running non-stop since the first bug happened, but
> so far the problem hasn't surfaced again :-(
>
> I've been using the kernel with the patch that you provided me
> (nf_tproxy.c). Is there a chance that patch fixed the problem?

This is a real bug, but I dont think it can fix your problem.

Looking again at your crash, we see RCX=0x720, decimal 1824

As its skb->len, we are freeing an skb that was collapsed or something
like that, since 1824 > 1460 (the normal MSS on ethernet)

GRO is off on your machine.

But coincidently 0x0720 is also a blank char for VGA screen...
(0x20 : ASCII space, 0x07 : default attribute)

So maybe you hit a corruption outside of network stack.



--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Felipe W Damasio on 13 Jul 2010 17:00
Hi Mr. Dumazet,

I used the patched kernel on the production machine and squid frooze again.

This is the dmesg message:


general protection fault: 0000 [#1] SMP
last sysfs file: /sys/devices/pci0000:00/0000:00:1f.3/i2c-0/name
CPU 1
Modules linked in:

Pid: 5533, comm: squid Not tainted 2.6.34 #6 DX58SO/
RIP: 0010:[<ffffffff81369b2a>] [<ffffffff81369b2a>] sock_rfree+0x26/0x37
RSP: 0018:ffff88042287fc20 EFLAGS: 00010206
RAX: 66c86f938964c696 RBX: ffff88034e8f9a00 RCX: 0000000000000720
RDX: ffff8803f0ce05c0 RSI: ffff8803d441960c RDI: ffff88034e8f9a00
RBP: ffff8803f0ee05c0 R08: ffffea000dcb9998 R09: 0000000000000000
R10: 000000000003d830 R11: ffff8803f0ee05c0 R12: 00000000000005a8
R13: 00000000000005a8 R14: 0000000000004378 R15: 0000000000000000
FS: 00007f4cf33ee710(0000) GS:ffff880001840000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000021d5fd0 CR3: 0000000422872000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process squid (pid: 5533, threadinfo ffff88042287e000, task ffff88042eb61a40)
Stack:
ffffffff8136ecda ffff88034e8f9a00 ffffffff8136ea8c ffff88034e8f9a00
<0> ffffffff813ab142 00000000000000d0 ffffffff8136f9f9 000000000eec60e2
<0> ffff88042eb61a40 ffff88042eb61a40 ffff88042eb61a40 00000000edca7300
Call Trace:
[<ffffffff8136ecda>] ? skb_release_head_state+0x6d/0xb7
[<ffffffff8136ea8c>] ? __kfree_skb+0x9/0x7d
[<ffffffff813ab142>] ? tcp_recvmsg+0x6a3/0x89a
[<ffffffff8136f9f9>] ? __alloc_skb+0x5e/0x14e
[<ffffffff81369dde>] ? sock_common_recvmsg+0x30/0x45
[<ffffffff81367b0f>] ? sock_aio_read+0xdd/0xf1
[<ffffffff813b6c97>] ? tcp_write_xmit+0x93e/0x96c
[<ffffffff810ac500>] ? do_sync_read+0xb0/0xf2
[<ffffffff810acf32>] ? vfs_read+0xb9/0xff
[<ffffffff810ad034>] ? sys_read+0x45/0x6e
[<ffffffff8100292b>] ? system_call_fastpath+0x16/0x1b
Code: ff ff ff ff c3 48 8b 57 18 8b 87 d8 00 00 00 48 8d 8a ac 00 00
00 f0 29 82 ac 00 00 00 48 8b 57 18 8b 8f d8 00 00 00 48 8b 42 38 <48>
83 b8 b0 00 00 00 00 74 06 01 8a f4 00 00 00 c3 41 57 41 89
RIP [<ffffffff81369b2a>] sock_rfree+0x26/0x37
RSP <ffff88042287fc20>
---[ end trace 22e6ca9ef825c0e6 ]---


Seems to be the same issue, right?

Cheers,

Felipe Damasio





2010/7/13 Eric Dumazet <eric.dumazet(a)gmail.com>:
> Le mardi 13 juillet 2010 � 11:49 -0300, Felipe W Damasio a �crit :
>> Hi Mr. Dumazet,
>>
>> 2010/7/13 Eric Dumazet <eric.dumazet(a)gmail.com>:
>> > I currently have no fresh ideas. If you want this problem to be solved,
>> > its important to setup in your lab a workload to trigger again and again
>> > the bug, in order to provide us more crash information.
>>
>> �Right. I've been running non-stop since the first bug happened, but
>> so far the problem hasn't surfaced again :-(
>>
>> �I've been using the kernel with the patch that you provided me
>> (nf_tproxy.c). Is there a chance that patch fixed the problem?
>
> This is a real bug, but I dont think it can fix your problem.
>
> Looking again at your crash, we see RCX=0x720, decimal 1824
>
> As its skb->len, we are freeing an skb that was collapsed or something
> like that, since 1824 > 1460 (the normal MSS on ethernet)
>
> GRO is off on your machine.
>
> But coincidently 0x0720 is also a blank char for VGA screen...
> (0x20 : ASCII space, 0x07 : default attribute)
>
> So maybe you hit a corruption outside of network stack.
>
>
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Felipe W Damasio on 13 Jul 2010 17:10
Hi,

2010/7/13 Felipe W Damasio <felipewd(a)gmail.com>:
> This is the dmesg message:

This error happened at 17:19:59.

A few seconds earlier, I have these on squid's logs:

2010/07/13 17:19:50| clientTryParseRequest: FD 1690
(189.113.65.55:52681) Invalid Request
2010/07/13 17:19:50| clientTryParseRequest: FD 5056
(189.113.74.101:2420) Invalid Request
2010/07/13 17:19:52| clientTryParseRequest: FD 26923
(189.113.74.101:2419) Invalid Request
2010/07/13 17:19:57| parseHttpRequest: Unsupported method 'PASS'
2010/07/13 17:19:57| clientTryParseRequest: FD 17786
(189.113.69.194:2422) Invalid Request
2010/07/13 17:19:57| parseHttpRequest: Unsupported method '<D2>Yk'
2010/07/13 17:19:57| clientTryParseRequest: FD 22554
(189.113.79.151:4225) Invalid Request
2010/07/13 17:19:59| httpReadReply: Excess data from "GET
http://webcs.msg.yahoo.com/crossdomain.xml"

Maybe with these two errors we can create some kind of trigger
program to help us duplicate this on the lab setup?

Cheers,

Felipe Damasio
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Eric Dumazet on 13 Jul 2010 23:30
Le mardi 13 juillet 2010 à 17:55 -0300, Felipe W Damasio a écrit :
> Hi Mr. Dumazet,
>
> I used the patched kernel on the production machine and squid frooze again.
>
> This is the dmesg message:
>
>
> general protection fault: 0000 [#1] SMP
> last sysfs file: /sys/devices/pci0000:00/0000:00:1f.3/i2c-0/name
> CPU 1
> Modules linked in:
>
> Pid: 5533, comm: squid Not tainted 2.6.34 #6 DX58SO/
> RIP: 0010:[<ffffffff81369b2a>] [<ffffffff81369b2a>] sock_rfree+0x26/0x37
> RSP: 0018:ffff88042287fc20 EFLAGS: 00010206
> RAX: 66c86f938964c696 RBX: ffff88034e8f9a00 RCX: 0000000000000720
> RDX: ffff8803f0ce05c0 RSI: ffff8803d441960c RDI: ffff88034e8f9a00
> RBP: ffff8803f0ee05c0 R08: ffffea000dcb9998 R09: 0000000000000000
> R10: 000000000003d830 R11: ffff8803f0ee05c0 R12: 00000000000005a8
> R13: 00000000000005a8 R14: 0000000000004378 R15: 0000000000000000
> FS: 00007f4cf33ee710(0000) GS:ffff880001840000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00000000021d5fd0 CR3: 0000000422872000 CR4: 00000000000006e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> Process squid (pid: 5533, threadinfo ffff88042287e000, task ffff88042eb61a40)
> Stack:
> ffffffff8136ecda ffff88034e8f9a00 ffffffff8136ea8c ffff88034e8f9a00
> <0> ffffffff813ab142 00000000000000d0 ffffffff8136f9f9 000000000eec60e2
> <0> ffff88042eb61a40 ffff88042eb61a40 ffff88042eb61a40 00000000edca7300
> Call Trace:
> [<ffffffff8136ecda>] ? skb_release_head_state+0x6d/0xb7
> [<ffffffff8136ea8c>] ? __kfree_skb+0x9/0x7d
> [<ffffffff813ab142>] ? tcp_recvmsg+0x6a3/0x89a
> [<ffffffff8136f9f9>] ? __alloc_skb+0x5e/0x14e
> [<ffffffff81369dde>] ? sock_common_recvmsg+0x30/0x45
> [<ffffffff81367b0f>] ? sock_aio_read+0xdd/0xf1
> [<ffffffff813b6c97>] ? tcp_write_xmit+0x93e/0x96c
> [<ffffffff810ac500>] ? do_sync_read+0xb0/0xf2
> [<ffffffff810acf32>] ? vfs_read+0xb9/0xff
> [<ffffffff810ad034>] ? sys_read+0x45/0x6e
> [<ffffffff8100292b>] ? system_call_fastpath+0x16/0x1b
> Code: ff ff ff ff c3 48 8b 57 18 8b 87 d8 00 00 00 48 8d 8a ac 00 00
> 00 f0 29 82 ac 00 00 00 48 8b 57 18 8b 8f d8 00 00 00 48 8b 42 38 <48>
> 83 b8 b0 00 00 00 00 74 06 01 8a f4 00 00 00 c3 41 57 41 89
> RIP [<ffffffff81369b2a>] sock_rfree+0x26/0x37
> RSP <ffff88042287fc20>
> ---[ end trace 22e6ca9ef825c0e6 ]---
>
>
> Seems to be the same issue, right?
>

Exactly the same. Only RAX value is different, its another chain.

BTW, 0x720 is not skb->len like I said earlier, but skb->truesize, and
0x720 is OK on a 64 bit machine for a regular packet.

48 8b 57 18 mov 0x18(%rdi),%rdx skb->sk
8b 87 d8 00 00 00 mov 0xd8(%rdi),%eax skb->truesize
48 8d 8a ac 00 00 00 lea 0xac(%rdx),%rcx
f0 29 82 ac 00 00 00 lock sub %eax,0xac(%rdx)
48 8b 57 18 mov 0x18(%rdi),%rdx skb->sk
8b 8f d8 00 00 00 mov 0xd8(%rdi),%ecx skb->truesize
48 8b 42 38 mov 0x38(%rdx),%rax sk->sk_prot
<48> 83 b8 b0 00 00 00 00 cmpq $0x0,0xb0(%rax)
74 06 je .+6
01 8a fa 00 00 00 add %ecx,0xfa(%rdx)


One thing to notice are the RDX and RBP values:

RDX: ffff8803f0ce05c0
RBP: ffff8803f0ee05c0

RDX being the sk pointer (and sk+0x38 contains the corrupted "sk_prot" value)
, we notice RBP contains same "sk" value + 0x200000 (2 Mbytes).

(same remark on your initial bug report)

Could you enable CONFIG_FRAME_POINTER=y in your config ?


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Patrick McHardy on 14 Jul 2010 07:50
On 09.07.2010 19:13, Eric Dumazet wrote:
> Le vendredi 09 juillet 2010 � 12:03 -0300, Felipe W Damasio a �crit :
>> Hi,
>>
>> 2010/7/8 Eric Dumazet <eric.dumazet(a)gmail.com>:
>>> Please try to reproduce a new report.
>>>
>>> It looks like a memory corruption, and it would be good to see if a
>>> common pattern is occurring.
>>
>> I'm trying..the thing is the freeze occured on the machine that sits
>> on a 200Mbps ISP in bridge-mode. Since the machine frooze, and the
>> whole ISP went down for a few minutes, I'm not allowed to run any
>> tests on it.
>>
>> I've setup the same scenario on a lab, but since last night been
>> unable to reproduce the bug. Maybe there's a clue on the this crash
>> below that can help me write some program to trigger the problem?
>>
>
> Reviewing tproxy stuff I spotted a problem in nf_tproxy_assign_sock()
> but I could not see how it could explain your crash.
>
> We can read uninitialized memory and trigger a fault in
> nf_tproxy_assign_sock(), not later in tcp_recvmsg()...
>
> David, Patrick, what do you think ?
>
> Thanks
>
> [PATCH] tproxy: nf_tproxy_assign_sock() can handle tw sockets
>
> transparent field of a socket is either inet_twsk(sk)->tw_transparent
> for timewait sockets, or inet_sk(sk)->transparent for other sockets
> (TCP/UDP).

I don't see anything preventing use of timewait sockets, so the
patch looks correct to me.

Applied to nf-2.6.git, thanks Eric.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
First  |  Prev  |  Next  |  Last
Pages: 1 2 3 4 5
Prev: QoS and/or fair queueing: Stateless NAT BUG
Next: Bluetooth: hidp: Add support for hidraw HIDIOCGFEATURE and HIDIOCSFEATURE