Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Andrew Morton]

(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

On Wed, 21 May 2008 02:45:59 -0700 (PDT) bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=10767
> 
>            Summary: Seg Fault Instead of Swapping

Strange description?

>            Product: Networking
>            Version: 2.5
>      KernelVersion: 2.6.25.4
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: IPV4
>         AssignedTo: shemminger@linux-foundation.org
>         ReportedBy: brian.vowell@gmail.com
> 
> 
> May 20 13:11:00 ishtar kernel: ------------[ cut here ]------------
> May 20 13:11:00 ishtar kernel: WARNING: at net/ipv4/tcp_input.c:2539
> tcp_ack+0xd2b/0x191f()

In 2.6.25 this is

	if (WARN_ON(!tp->sacked_out && tp->fackets_out))
		tp->fackets_out = 0;

> May 20 13:11:00 ishtar kernel: Modules linked in: fuse dm_mirror dm_multipath
> dm_mod cfi_cmdset_0002 cfi_util jedec_probe button cfi_probe gen_probe k8temp
> ck804xrom hwmon mtd usb_storage chipreg serio_raw map_funcs i2c_nforce2 pcspkr
> i2c_core sg pata_amd cciss ata_generic pata_acpi sata_nv libata sd_mod scsi_mod
> raid456 async_xor async_memcpy async_tx xor raid1 uhci_hcd ohci_hcd ssb
> ehci_hcd [last unloaded: scsi_wait_scan]
> May 20 13:11:00 ishtar kernel: Pid: 0, comm: swapper Not tainted 2.6.25.4 #1
> May 20 13:11:00 ishtar kernel:
> May 20 13:11:00 ishtar kernel: Call Trace:
> May 20 13:11:00 ishtar kernel:  <IRQ>  [<ffffffff81034481>]
> warn_on_slowpath+0x51/0x63
> May 20 13:11:00 ishtar kernel:  [<ffffffff81023577>] kernel_map_pages+0xe8/0xed
> May 20 13:11:00 ishtar kernel:  [<ffffffff8103ca36>] lock_timer_base+0x26/0x4c
> May 20 13:11:00 ishtar kernel:  [<ffffffff812baa38>] tcp_snd_test+0x17/0xdf
> May 20 13:11:00 ishtar kernel:  [<ffffffff812bab4d>] tcp_may_send_now+0x4d/0x5a
> May 20 13:11:00 ishtar kernel:  [<ffffffff812b68ce>] tcp_ack+0xd2b/0x191f
> May 20 13:11:00 ishtar kernel:  [<ffffffff812b9dbc>]
> tcp_rcv_established+0xe2/0x8ce
> May 20 13:11:00 ishtar kernel:  [<ffffffff812bffba>] tcp_v4_do_rcv+0x2c2/0x48b
> May 20 13:11:00 ishtar kernel:  [<ffffffff8129a07a>] __qdisc_run+0xf6/0x1c8
> May 20 13:11:00 ishtar kernel:  [<ffffffff812ae376>]
> __inet_lookup_established+0xdf/0x17b
> May 20 13:11:00 ishtar kernel:  [<ffffffff812c1d10>] tcp_v4_rcv+0x6a3/0x700
> May 20 13:11:00 ishtar kernel:  [<ffffffff812a7558>]
> ip_local_deliver+0xd4/0x18e
> May 20 13:11:00 ishtar kernel:  [<ffffffff812a7b0d>] ip_rcv+0x4fb/0x53a
> May 20 13:11:00 ishtar kernel:  [<ffffffff8128a2b7>]
> netif_receive_skb+0x351/0x372
> May 20 13:11:00 ishtar kernel:  [<ffffffff8124150d>] tg3_poll+0x588/0x7df
> May 20 13:11:00 ishtar kernel:  [<ffffffff8128c2ce>] net_rx_action+0xb6/0x1bf
> May 20 13:11:00 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
> May 20 13:11:00 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
> May 20 13:11:00 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
> default_idle+0x0/0x55
> May 20 13:11:00 ishtar kernel:  [<ffffffff8101c138>] lapic_next_event+0x0/0xa
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 20 13:11:00 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a
> May 20 13:11:00 ishtar kernel:
> May 20 13:11:00 ishtar kernel: ---[ end trace f970ab335f443aca ]---

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Andrew Morton]

On Wed, 21 May 2008 11:40:43 -0700 "Brian Vowell" <brian.vowell@gmail.com> wrote:

> Please forgive my lack of technical skills-- I am not a developer.

Thank you for reporting this kernel bug!

> The bug report referenced below recently occurred on a pretty busy file
> server of mine running Fedora 8 with a custom 2.6.25.4 kernel.  The attached
> hardware RAID controller presents 12 LUNs, which were striped using the
> Linux mdadm tools, and then the Linux LVM was used to create a single
> logical volume.  The filesystem used is XFS.
> 
> Since upgrading from 2.6.25.3 to 2.6.25.4, my log has shown a large number
> of errors that I don't possess the skills to diagnose which component is
> actually causing the errors.  I can verify however, that the hardware is
> good.  I have run memtest86 and the vendor's diagnostic tools and verified
> that everything is running well.
> 
> The errors in /var/log/messages look like this:
> May 19 06:30:30 ishtar kernel: Call Trace:
> May 19 06:30:30 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
> __alloc_pages+0x33f/0x35a
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
> May 19 06:30:30 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
> May 19 06:30:30 ishtar kernel:  [<ffffffff81093bba>]
> __slab_alloc+0x212/0x43b
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff81094bd6>]
> __kmalloc_node_track_caller+0x75/0xab
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff8123a405>]
> tg3_alloc_rx_skb+0xc4/0x153
> May 19 06:30:30 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128c2ce>]
> net_rx_action+0xb6/0x1bf
> May 19 06:30:30 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
> May 19 06:30:30 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
> May 19 06:30:30 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
> default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8101c138>]
> lapic_next_event+0x0/0xa
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a
> 
> The hardware is an HP Proliant DL145G2, Dual Core Opteron 275 processor, 4GB
> of RAM, dual Broadcom GigE NICs bonded with Linux bonding driver, dual
> software RAID SATA disks for boot and swap.
> 
> The call trace included with the bug report is the only one that appears in
> the log with the "cut here" lines.
> 

OK, that is the TCP code performing self-checks and finding an
unexpected state.  

I was just a bit concerned about the "segfault" part of the
description.  Because often when the kernel crashes this appears to the
operator as a userspace segfault.  But the above trace isn't a kernel
crash - it's just a warning and the kernel does attept to fix things up
in this case.

If however you were really seeing unexpected segfaults then it could be
the case that the kernel is crashing.  But I assume this is not the
case, and that the text "Oops" does not appear in the logs.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

On Wed, 21 May 2008, Brian Vowell wrote:

> Please forgive my lack of technical skills-- I am not a developer.

And I'm having problem in figuring out what is actually being reported 
here... so pleasy forgive my possibly stupid comments... :-)

> The bug report referenced below recently occurred on a pretty busy file
> server of mine running Fedora 8 with a custom 2.6.25.4 kernel.  The attached
> hardware RAID controller presents 12 LUNs, which were striped using the
> Linux mdadm tools, and then the Linux LVM was used to create a single
> logical volume.  The filesystem used is XFS.
> 
> Since upgrading from 2.6.25.3 to 2.6.25.4, my log has shown a large number
> of errors that I don't possess the skills to diagnose which component is
> actually causing the errors.  I can verify however, that the hardware is
> good.  I have run memtest86 and the vendor's diagnostic tools and verified
> that everything is running well.

At least the TCP thing is known to be in core TCP but it's just hard to 
debug and that's why it hasn't yet been closed, no hw is suspect due to 
it. But this other stacktrace seems to be something unrelated to TCP...:

> The errors in /var/log/messages look like this:
> May 19 06:30:30 ishtar kernel: Call Trace:
> May 19 06:30:30 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
> __alloc_pages+0x33f/0x35a
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
> May 19 06:30:30 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
> May 19 06:30:30 ishtar kernel:  [<ffffffff81093bba>]
> __slab_alloc+0x212/0x43b
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff81094bd6>]
> __kmalloc_node_track_caller+0x75/0xab
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 19 06:30:30 ishtar kernel:  [<ffffffff8123a405>]
> tg3_alloc_rx_skb+0xc4/0x153
> May 19 06:30:30 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df
> May 19 06:30:30 ishtar kernel:  [<ffffffff8128c2ce>]
> net_rx_action+0xb6/0x1bf
> May 19 06:30:30 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
> May 19 06:30:30 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
> May 19 06:30:30 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
> default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8101c138>]
> lapic_next_event+0x0/0xa
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
> May 19 06:30:30 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a
> 
> The hardware is an HP Proliant DL145G2, Dual Core Opteron 275 processor, 4GB
> of RAM, dual Broadcom GigE NICs bonded with Linux bonding driver, dual
> software RAID SATA disks for boot and swap.
> 
> The call trace included with the bug report is the only one that appears in
> the log with the "cut here" lines.
> 
> 
> 
> 
> On 5/21/08, Andrew Morton <akpm@linux-foundation.org> wrote:
> >
> >
> > (switched to email.  Please respond via emailed reply-to-all, not via the
> > bugzilla web interface).
> >
> > On Wed, 21 May 2008 02:45:59 -0700 (PDT) bugme-daemon@bugzilla.kernel.orgwrote:
> >
> > > http://bugzilla.kernel.org/show_bug.cgi?id=10767
> > >
> > >            Summary: Seg Fault Instead of Swapping
> >
> > Strange description?
> >
> > >            Product: Networking
> > >            Version: 2.5
> > >      KernelVersion: 2.6.25.4
> > >           Platform: All
> > >         OS/Version: Linux
> > >               Tree: Mainline
> > >             Status: NEW
> > >           Severity: normal
> > >           Priority: P1
> > >          Component: IPV4
> > >         AssignedTo: shemminger@linux-foundation.org
> > >         ReportedBy: brian.vowell@gmail.com
> > >
> > >
> > > May 20 13:11:00 ishtar kernel: ------------[ cut here ]------------
> > > May 20 13:11:00 ishtar kernel: WARNING: at net/ipv4/tcp_input.c:2539
> > > tcp_ack+0xd2b/0x191f()
> >
> > In 2.6.25 this is
> >
> >         if (WARN_ON(!tp->sacked_out && tp->fackets_out))
> >                 tp->fackets_out = 0;

...This TCP warning isn't sign of a problem that would cause corruption of 
any kind (and the state inconsistency gets repaired there as well!), we're 
debugging this already with couple of other people, so unless you have 
some very good reproducer case you'll just have to wait a bit.

-- 
 i.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 3596 bytes --]

On Wed, 21 May 2008, Brian Vowell wrote:

> On 5/21/08, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote:
> >
> > On Wed, 21 May 2008, Brian Vowell wrote:
> >
> > ...This TCP warning isn't sign of a problem that would cause corruption of
> > any kind (and the state inconsistency gets repaired there as well!), we're
> > debugging this already with couple of other people, so unless you have
> > some very good reproducer case you'll just have to wait a bit.
> 
> I don't mind waiting.  I just thought that since this happened so quickly
> after upgrading to the 2.6.25.4 kernel that it might be something that was
> related to changes from 2.6.25.3.

It's just due to luck (that's what makes debugging it hard). There isn't 
anything even remotely related changed in 2.6.25.3 -> 2.6.25.4 :-). Of 
course, if you really want to you can always add the debug patch the other 
2539-warning tracking people already use:

  http://marc.info/?l=linux-netdev&m=120972551120080&w=2

It will add some expensive verifications that are run multiple times per 
ACK to validate TCP's internal consistency which is normally just 
"assumed" to be valid due to performance reasons. Please note what I said 
about CONFIG_LOG_BUF_SHIFT there so that the previous disaster doesn't 
repeat itself... :-) Then you just need to occassionally see if it has 
triggered (from kernel logs).

> The only thing that I can do in regards to assisting is to provide info
> about what triggers the bug and/or provide access to my system to anyone who
> wants to take a closer look.
>
> At the time the bug occurred, the system was running two I/O intensive
> applications.  The first was the "xfs_fsr" tool to defragment the XFS
> filesystem (it was pushing about 25-30MB/sec to the array), and the rtorrent
> BitTorrent client, which was pulling down a Fedora ISO at about 25mbps, and
> writing to a SATA device, separate from the array where the XFS filesystem
> lives.  In the past, I have seen the rtorrent client create oops errors when
> running within a Xen VM.  This problem only occurred when the guest domU VM
> was running XFS for its root filesystem and the host dom0 that provided the
> filestore for the gues was also running XFS.  (Running the guest on ext3
> stops the oops errors).  It may or may not be related to this error that I'm
> reporting, but considering that the rtorrent app is the same app that was
> running at the time of both segfaults and the oops errors, it makes me
> suspicious and I thought that I'd mention it.

All other details but torrent are most likely irrelevant, it could be 
that the added load has some significance to window behavior but that's 
not too likely to make difference. More important would be to know with 
which host torrent was communicating at the time of the WARNING, and even 
more importantly, what "special" happened between that host and your host 
in the network. Once that becomes known thing, this will be easy to 
reproduce and it might even be that the fix is then something dead 
obvious.

> Just to be clear, the bug that I'm reporting is running on a clean system,
> with no Xen installed on it.
> 
> Otherwise, it's really like a bug in real life-- a small creature that is
> annoying but doesn't really harm anything.

The thing I'm still concerned in this report is the presence of the other 
stacktrace which seemed to not be TCP related. Could you confirm/list all 
the other problems than the WARNING net/ipv4/tcp_input.c:2539(+its 
stacktrace) that you have been seeing. ...I'm saying this because it might 
be worth of pursuing further.

-- 
 i.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

On Fri, 23 May 2008, Brian Vowell wrote:

> I applied the ipv4 patch.  Here are two traces that just showed up:
> 
> ------------[ cut here ]------------
> WARNING: at net/ipv4/tcp_input.c:3297 tcp_ack+0xd58/0xeba()
> Modules linked in: dm_mirror dm_multipath dm_mod cfi_cmdset_0002 cfi_util
> button jedec_probe cfi_probe gen_probe ck804xrom i2c_nforce2 mtd chipreg
> map_funcs k8temp sg hwmon pcspkr i2c_core serio_raw pata_amd cciss
> ata_generic pata_acpi sata_nv libata sd_mod scsi_mod raid456 async_xor
> async_memcpy async_tx xor raid1 uhci_hcd ohci_hcd ssb ehci_hcd [last
> unloaded: scsi_wait_scan]
> Pid: 0, comm: swapper Not tainted 2.6.25.4 #1
> 
> Call Trace:
>  <IRQ>  [<ffffffff81034481>] warn_on_slowpath+0x51/0x63
>  [<ffffffff8128cdaf>] dev_queue_xmit+0x25b/0x284
>  [<ffffffff812ab9fa>] ip_queue_xmit+0x2cc/0x31f
>  [<ffffffff812b0e3b>] sk_stream_alloc_skb+0x2f/0xd2
>  [<ffffffff8104a1bb>] getnstimeofday+0x2f/0x83
>  [<ffffffff812bb83d>] tcp_transmit_skb+0x775/0x7a4
>  [<ffffffff812b760a>] tcp_ack+0xd58/0xeba
>  [<ffffffff812ba74b>] tcp_rcv_established+0x7b9/0x8ce
>  [<ffffffff812c05cd>] tcp_v4_do_rcv+0x2c2/0x48b
>  [<ffffffff8129a07a>] __qdisc_run+0xf6/0x1c8
>  [<ffffffff812ae376>] __inet_lookup_established+0xdf/0x17b
>  [<ffffffff812c2528>] tcp_v4_rcv+0x6a3/0x700
>  [<ffffffff812a7558>] ip_local_deliver+0xd4/0x18e
>  [<ffffffff812a7b0d>] ip_rcv+0x4fb/0x53a
>  [<ffffffff8128a2b7>] netif_receive_skb+0x351/0x372
>  [<ffffffff8124150d>] tg3_poll+0x588/0x7df
>  [<ffffffff8128c2ce>] net_rx_action+0xb6/0x1bf
>  [<ffffffff8103919b>] __do_softirq+0x65/0xce
>  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
>  [<ffffffff8100e544>] do_softirq+0x2c/0x68
>  [<ffffffff810390f2>] irq_exit+0x3f/0x83
>  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
>  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
>  <EOI>  [<ffffffff8100adc8>] default_idle+0x0/0x55
>  [<ffffffff8101c138>] lapic_next_event+0x0/0xa
>  [<ffffffff8100adc8>] default_idle+0x0/0x55
>  [<ffffffff8100adf9>] default_idle+0x31/0x55
>  [<ffffffff8100adf4>] default_idle+0x2c/0x55
>  [<ffffffff8100adc8>] default_idle+0x0/0x55
>  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a
> 
> ---[ end trace aae73dd976dfcd54 ]---
> TCP wq(s)  S                <
> TCP wq(h) ++h-----+-----+---<
> l0 s1 f2 p18 seq: wq1288576867, su1288576867 hs1288579763 sn1288602883

Aha, it seems you got TCP into the invalid state which I recently added 
check for :-), I'll try to figure out how that could still happen (I think 
I tried to find such code path already earlier but it seems that there's 
still something I've overlooked). Though this is not directly going to 
cause the 2539 WARNING, yet it could, after some other (probably rare 
condition) possibly lead to that as well if this invariant is assumed to 
hold while doing some state manipulation elsewhere in TCP (though I 
think that's not too likely). In case you don't see them too often, you 
can well continue with the patch in order to find the cause for 2539 as 
well (and just ignore those occassional net/ipv4/tcp_input.c:3297 ones for 
now).

Thanks,

-- 
 i.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

On Fri, 23 May 2008, Brian Vowell wrote:

> > Aha, it seems you got TCP into the invalid state which I recently added
> > check for :-), I'll try to figure out how that could still happen (I think
> > I tried to find such code path already earlier but it seems that there's
> > still something I've overlooked). Though this is not directly going to
> > cause the 2539 WARNING, yet it could, after some other (probably rare
> > condition) possibly lead to that as well if this invariant is assumed to
> > hold while doing some state manipulation elsewhere in TCP (though I
> > think that's not too likely). In case you don't see them too often, you
> > can well continue with the patch in order to find the cause for 2539 as
> > well (and just ignore those occassional net/ipv4/tcp_input.c:3297 ones for
> > now).
> 
> 
> Do you want me to continue emailing these traces as they appear in my logs?

...Yes, in case you get something different than the WARNING at 3297.
I have at least one suspect already which could lead to that 3297 :-).

-- 
 i.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 3961 bytes --]

On Sat, 24 May 2008, Brian Vowell wrote:

> Here are more traces.  They all are warnings at 3297.

Hmm, likely fix to that included below (you might not be able to 
reproduce it anymore though because it's very sensitive to network 
behavior, ie., in case the peer you were communicating with isn't
there any more the necessary events simply won't happen). 

There seems to be yet another candidate in tcp_fastretrans_alert() that 
could cause it but it's extremely unlikely to occur in practice. ...I'll 
fix this one separately later on.

And this isn't exactly there problem we were tracking for but it's nice 
that it showed up as well (so you might want to keep the debug patch 
still applied too)... :-)

-- 
 i.


--
[PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))

It is possible that this skip path causes TCP to end up into an
invalid state where ca_state was left to CA_Open while some
segments already came into sacked_out. If next valid ACK doesn't
contain new SACK information TCP fails to enter into
tcp_fastretrans_alert(). Thus at least high_seq is set
incorrectly to a too high seqno because some new data segments
could be sent in between (and also, limited transmit is not
being correctly invoked there). Reordering in both directions
can easily cause this situation to occur.

I guess we would want to use tcp_moderate_cwnd(tp) there as well
as it may be possible to use this to trigger oversized burst to
network by sending an old ACK with huge amount of SACK info, but
I'm a bit unsure about its effects (mainly to FlightSize), so to
be on the safe side I just currently fixed it minimally to keep
TCP's state consistent (obviously, such nasty ACKs have been
possible this far). Though it seems that FlightSize is already
underestimated by some amount, so probably on the long term we
might want to trigger recovery there too, if appropriate, to make
FlightSize calculation to resemble reality at the time when the
losses where discovered (but such change scares me too much now
and requires some more thinking anyway how to do that as it
likely involves some code shuffling).

This bug was found by Brian Vowell while running my TCP debug
patch to find cause of another TCP issue (fackets_out
miscount).

Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi>
---
 net/ipv4/tcp_input.c |   29 +++++++++++++++++++----------
 1 files changed, 19 insertions(+), 10 deletions(-)

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index d9936a2..be53021 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c
@@ -2483,6 +2483,20 @@ static inline void tcp_complete_cwr(struct sock *sk)
 	tcp_ca_event(sk, CA_EVENT_COMPLETE_CWR);
 }
 
+static void tcp_try_keep_open(struct sock *sk)
+{
+	struct tcp_sock *tp = tcp_sk(sk);
+	int state = TCP_CA_Open;
+
+	if (tcp_left_out(tp) || tp->retrans_out || tp->undo_marker)
+		state = TCP_CA_Disorder;
+
+	if (inet_csk(sk)->icsk_ca_state != state) {
+		tcp_set_ca_state(sk, state);
+		tp->high_seq = tp->snd_nxt;
+	}
+}
+
 static void tcp_try_to_open(struct sock *sk, int flag)
 {
 	struct tcp_sock *tp = tcp_sk(sk);
@@ -2496,15 +2510,7 @@ static void tcp_try_to_open(struct sock *sk, int flag)
 		tcp_enter_cwr(sk, 1);
 
 	if (inet_csk(sk)->icsk_ca_state != TCP_CA_CWR) {
-		int state = TCP_CA_Open;
-
-		if (tcp_left_out(tp) || tp->retrans_out || tp->undo_marker)
-			state = TCP_CA_Disorder;
-
-		if (inet_csk(sk)->icsk_ca_state != state) {
-			tcp_set_ca_state(sk, state);
-			tp->high_seq = tp->snd_nxt;
-		}
+		tcp_try_keep_open(sk);
 		tcp_moderate_cwnd(tp);
 	} else {
 		tcp_cwnd_down(sk, flag);
@@ -3312,8 +3318,11 @@ no_queue:
 	return 1;
 
 old_ack:
-	if (TCP_SKB_CB(skb)->sacked)
+	if (TCP_SKB_CB(skb)->sacked) {
 		tcp_sacktag_write_queue(sk, skb, prior_snd_una);
+		if (icsk->icsk_ca_state == TCP_CA_Open)
+			tcp_try_keep_open(sk);
+	}
 
 uninteresting_ack:
 	SOCK_DEBUG(sk, "Ack %u out of %u:%u\n", ack, tp->snd_una, tp->snd_nxt);
-- 
1.5.2.2

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[David Miller]

From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi>
Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)

Ilpo, do you want me to apply this to net-2.6?

> [PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))
> 
> It is possible that this skip path causes TCP to end up into an
> invalid state where ca_state was left to CA_Open while some
> segments already came into sacked_out. If next valid ACK doesn't
> contain new SACK information TCP fails to enter into
> tcp_fastretrans_alert(). Thus at least high_seq is set
> incorrectly to a too high seqno because some new data segments
> could be sent in between (and also, limited transmit is not
> being correctly invoked there). Reordering in both directions
> can easily cause this situation to occur.
> 
> I guess we would want to use tcp_moderate_cwnd(tp) there as well
> as it may be possible to use this to trigger oversized burst to
> network by sending an old ACK with huge amount of SACK info, but
> I'm a bit unsure about its effects (mainly to FlightSize), so to
> be on the safe side I just currently fixed it minimally to keep
> TCP's state consistent (obviously, such nasty ACKs have been
> possible this far). Though it seems that FlightSize is already
> underestimated by some amount, so probably on the long term we
> might want to trigger recovery there too, if appropriate, to make
> FlightSize calculation to resemble reality at the time when the
> losses where discovered (but such change scares me too much now
> and requires some more thinking anyway how to do that as it
> likely involves some code shuffling).
> 
> This bug was found by Brian Vowell while running my TCP debug
> patch to find cause of another TCP issue (fackets_out
> miscount).
> 
> Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi>

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 1124 bytes --]

On Tue, 3 Jun 2008, David Miller wrote:

> From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi>
> Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)
> 
> Ilpo, do you want me to apply this to net-2.6?

Yes thanks, it is necessary to keep the state consistent (it also explains 
some .22/23 time left_out warn_ons too which were mysterious back then).
Also -stable (I guess it would be necessary to almost any older stable
too though some older ones might want to sync left_out on that same place 
too).

It was nice that this path was also triggered while running the TCP 
debug patch (I haven't gotten a one in here), otherwise we would never
have known though I started to suspect that such path existed once I
tried to analyze those left_out problems (before it got dropped 
altogether), but I just couldn't find the problem because it lies on 
such "error path" which was too easy to overlook.

I also finally have found the cause to the !sacked_out && fackets_out
trap :-). ...I'll post the fix to that later today to relevant parties.

> > [PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))


-- 
 i.

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[David Miller]

From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi>
Date: Wed, 4 Jun 2008 10:12:04 +0300 (EEST)

> On Tue, 3 Jun 2008, David Miller wrote:
> 
> > From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi>
> > Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)
> > 
> > Ilpo, do you want me to apply this to net-2.6?
> 
> Yes thanks, it is necessary to keep the state consistent (it also explains 
> some .22/23 time left_out warn_ons too which were mysterious back then).
> Also -stable (I guess it would be necessary to almost any older stable
> too though some older ones might want to sync left_out on that same place 
> too).
> 
> It was nice that this path was also triggered while running the TCP 
> debug patch (I haven't gotten a one in here), otherwise we would never
> have known though I started to suspect that such path existed once I
> tried to analyze those left_out problems (before it got dropped 
> altogether), but I just couldn't find the problem because it lies on 
> such "error path" which was too easy to overlook.

Ok I've add the patch to net-2.6, thanks!

> I also finally have found the cause to the !sacked_out && fackets_out
> trap :-). ...I'll post the fix to that later today to relevant parties.

I'll have a look at this too :-)

Thanks for all of your incredible work on TCP bug fixing!

Re: [Bugme-new] [Bug 10767] New: Seg Fault Instead of Swapping

[Ilpo Järvinen]

On Fri, 23 May 2008, Brian Vowell wrote:

> Here are some of the others that show in the logs:
> 
> This one repeats four times, and then again multiple times every minute
> afterwards for about 30 minutes.
> May 18 19:31:00 ishtar kernel: pdflush: page allocation failure. order:3,
> mode:0x4020

I think that the problem here is that tg3 tries to allocate a large 
contiguous memory block which isn't available.

> May 18 19:31:00 ishtar kernel: Pid: 15300, comm: pdflush Not tainted
> 2.6.25.4 #1
> May 18 19:31:00 ishtar kernel:
> May 18 19:31:00 ishtar kernel: Call Trace:
> May 18 19:31:00 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
> __alloc_pages+0x33f/0x35a
> May 18 19:31:00 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
> May 18 19:31:00 ishtar kernel:  [<ffffffff81093bba>]
> __slab_alloc+0x212/0x43b
> May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 18 19:31:00 ishtar kernel:  [<ffffffff81094bd6>]
> __kmalloc_node_track_caller+0x75/0xab
> May 18 19:31:00 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
> May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]
> __netdev_alloc_skb+0x29/0x43
> May 18 19:31:00 ishtar kernel:  [<ffffffff8123a405>]
> tg3_alloc_rx_skb+0xc4/0x153
> May 18 19:31:00 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df


...but I'm probably not much of help with it.


-- 
 i.