Deadlocks

Deadlocks

[Phil Oester]

For the past 3 months I've been experiencing deadlocks on some heavily
used gateway/firewall boxes which started after upgrading from 2.4.20.

I can confirm that moving back to 2.4.20 stops the hangs, moving to 2.4.21
(or any kernel after that) makes them return.  I am in the process of testing
out each individual 2.4.21-pre to find out where exactly the problem is.

In the interim, I've collected some SysRq output which may help in the
analysis.  Below are two separate lockups on a 2.6.6 kernel.  Anyone have
any bright ideas?

Phil Oester


Lockup #1:
Pid: 0, comm:              swapper
EIP: 0060:[<c024a3e7>] CPU: 1
EIP is at __write_lock_failed+0xf/0x20
 EFLAGS: 00000287    Not tainted  (2.6.6)
EAX: c0283360 EBX: ffffffff ECX: 7d9d14aa EDX: ee83c1e0
ESI: f454b910 EDI: ffffffff EBP: 0000007d DS: 007b ES: 007b
CR0: 8005003b CR2: 08076ac4 CR3: 37b34000 CR4: 00000690
Call Trace:
 [<c0237f28>] .text.lock.ip_conntrack_core+0x7d/0xd5
 [<c023cf6d>] do_bindings+0x8d/0x260
 [<c0238855>] try_rfc959+0x25/0x30
 [<c0238dd7>] help+0x2f7/0x430
 [<c0238830>] try_rfc959+0x0/0x30
 [<c0238251>] tcp_packet+0xd1/0x160
 [<c0236ea0>] ip_conntrack_in+0x100/0x220
 [<c01fd182>] nf_iterate+0x72/0xb0
 [<c0205fc0>] ip_rcv_finish+0x0/0x245
 [<c01fd468>] nf_hook_slow+0x78/0x110
 [<c0205fc0>] ip_rcv_finish+0x0/0x245
 [<c0205da1>] ip_rcv+0x3c1/0x480
 [<c0205fc0>] ip_rcv_finish+0x0/0x245
 [<c01effe2>] alloc_skb+0x32/0xd0
 [<c01f4d72>] netif_receive_skb+0x162/0x190
 [<c01c9889>] e1000_clean_rx_irq+0x399/0x410
 [<c01c9244>] e1000_clean+0x34/0xb0
 [<c01f4f3f>] net_rx_action+0x7f/0x110
 [<c011ae84>] __do_softirq+0xb4/0xc0
 [<c0106b9c>] do_softirq+0x4c/0x60
 =======================
 [<c0106275>] do_IRQ+0x145/0x180
 [<c010467c>] common_interrupt+0x18/0x20
 [<c0101e20>] default_idle+0x0/0x40
 [<c0101e4c>] default_idle+0x2c/0x40
 [<c0101edb>] cpu_idle+0x3b/0x50
 [<c01177b7>] __call_console_drivers+0x57/0x60
 [<c01178af>] call_console_drivers+0x7f/0x100


Lockup #2:
Pid: 0, comm:              swapper
EIP: 0060:[<c0261bd0>] CPU: 0
EIP is at .text.lock.ip_nat_ftp+0x19/0x29
 EFLAGS: 00000286    Not tainted  (2.6.6)
EAX: 00000001 EBX: c0306000 ECX: d31c3034 EDX: eaeb8ac0
ESI: 00000019 EDI: eaeb8a48 EBP: c0306d24 DS: 007b ES: 007b
CR0: 8005003b CR2: 4024f0ec CR3: 31515000 CR4: 00000690
Call Trace:
 [<c0260592>] tcp_exp_matches_pkt+0x32/0x79
 [<c0266e5f>] do_bindings+0x34f/0x570
 [<c0264c17>] ip_nat_fn+0x77/0x310
 [<c021f0be>] nf_iterate+0x6e/0xc0
 [<c022dcb0>] ip_finish_output2+0x0/0x1cb
 [<c021f406>] nf_hook_slow+0x86/0x150
 [<c022dcb0>] ip_finish_output2+0x0/0x1cb
 [<c022b8b3>] ip_finish_output+0x43/0x50
 [<c022dcb0>] ip_finish_output2+0x0/0x1cb
 [<c022a47c>] ip_forward_finish+0x2c/0x50
 [<c021f45a>] nf_hook_slow+0xda/0x150
 [<c022a450>] ip_forward_finish+0x0/0x50
 [<c022a3b7>] ip_forward+0x137/0x1d0
 [<c022a450>] ip_forward_finish+0x0/0x50
 [<c02290b8>] ip_rcv_finish+0x1e8/0x25d
 [<c021f0be>] nf_iterate+0x6e/0xc0
 [<c0228ed0>] ip_rcv_finish+0x0/0x25d
 [<c021f45a>] nf_hook_slow+0xda/0x150
 [<c0228ed0>] ip_rcv_finish+0x0/0x25d
 [<c0228cad>] ip_rcv+0x18d/0x240
 [<c0228ed0>] ip_rcv_finish+0x0/0x25d
 [<c0215a14>] netif_receive_skb+0x174/0x1a0
 [<c01e60f8>] e1000_clean_rx_irq+0x3d8/0x490
 [<c01e5a2c>] e1000_clean+0x3c/0xb0
 [<c0215bf0>] net_rx_action+0x90/0x130
 [<c011f204>] __do_softirq+0xb4/0xc0
 [<c010764f>] do_softirq+0x4f/0x60
 =======================
 [<c0106979>] do_IRQ+0x1a9/0x260
 [<c011091c>] smp_apic_timer_interrupt+0xcc/0x130
 [<c0104bb0>] common_interrupt+0x18/0x20
 [<c0102150>] default_idle+0x0/0x40
 [<c010217f>] default_idle+0x2f/0x40
 [<c010220b>] cpu_idle+0x3b/0x50
 [<c02d7520>] unknown_bootoption+0x0/0x120
 [<c02d7943>] start_kernel+0x173/0x1c0
 [<c02d7520>] unknown_bootoption+0x0/0x120

Re: Deadlocks

[Jozsef Kadlecsik]

On Wed, 9 Jun 2004, Phil Oester wrote:

> For the past 3 months I've been experiencing deadlocks on some heavily
> used gateway/firewall boxes which started after upgrading from 2.4.20.
>
> I can confirm that moving back to 2.4.20 stops the hangs, moving to 2.4.21
> (or any kernel after that) makes them return.  I am in the process of testing
> out each individual 2.4.21-pre to find out where exactly the problem is.
>
> In the interim, I've collected some SysRq output which may help in the
> analysis.  Below are two separate lockups on a 2.6.6 kernel.  Anyone have
> any bright ideas?

Could you try out the 05_linux-2.4.26-orphaned_expect.patch or
05_linux-2.6.6-orphaned_expect.patch depending on the kernel
from pom-ng/updates? I think that is the fix for your lockups.

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlec@sunserv.kfki.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : KFKI Research Institute for Particle and Nuclear Physics
          H-1525 Budapest 114, POB. 49, Hungary

Re: Deadlocks

[Phil Oester]

I always apply the orphaned expectations patch (I'm the one who tracked that
one down and submitted the original patch ;-)

That is not the problem here -- this is a locking bug as shown by the SysRq
output.  I'm temporarily running 2.6.6 without SMP support to work around
it.

Phil

On Thu, Jun 10, 2004 at 10:07:16AM +0200, Jozsef Kadlecsik wrote:
> On Wed, 9 Jun 2004, Phil Oester wrote:
> 
> > For the past 3 months I've been experiencing deadlocks on some heavily
> > used gateway/firewall boxes which started after upgrading from 2.4.20.
> >
> > I can confirm that moving back to 2.4.20 stops the hangs, moving to 2.4.21
> > (or any kernel after that) makes them return.  I am in the process of testing
> > out each individual 2.4.21-pre to find out where exactly the problem is.
> >
> > In the interim, I've collected some SysRq output which may help in the
> > analysis.  Below are two separate lockups on a 2.6.6 kernel.  Anyone have
> > any bright ideas?
> 
> Could you try out the 05_linux-2.4.26-orphaned_expect.patch or
> 05_linux-2.6.6-orphaned_expect.patch depending on the kernel
> from pom-ng/updates? I think that is the fix for your lockups.

Re: Deadlocks

[Patrick McHardy]

On Wed, 2004-06-09 at 20:09, Phil Oester wrote:
> For the past 3 months I've been experiencing deadlocks on some heavily
> used gateway/firewall boxes which started after upgrading from 2.4.20.
> 
> I can confirm that moving back to 2.4.20 stops the hangs, moving to 2.4.21
> (or any kernel after that) makes them return.  I am in the process of testing
> out each individual 2.4.21-pre to find out where exactly the problem is.
> 
> In the interim, I've collected some SysRq output which may help in the
> analysis.  Below are two separate lockups on a 2.6.6 kernel.  Anyone have
> any bright ideas?

This looks like the problem I described a couple of month ago:
http://lists.netfilter.org/pipermail/netfilter-devel/2003-November/013130.html
I went through the 2.4.21 patch, but couldn't find anything that looks
related to this. The patch attached to the email above should apply to
something around 2.4.23. Please also enable CONFIG_NETFILTER_DEBUG, so
we can see where exactly the problem occurs.

Regards
Patrick

> 
> Phil Oester
> 
> 
> Lockup #1:
> Pid: 0, comm:              swapper
> EIP: 0060:[<c024a3e7>] CPU: 1
> EIP is at __write_lock_failed+0xf/0x20
>  EFLAGS: 00000287    Not tainted  (2.6.6)
> EAX: c0283360 EBX: ffffffff ECX: 7d9d14aa EDX: ee83c1e0
> ESI: f454b910 EDI: ffffffff EBP: 0000007d DS: 007b ES: 007b
> CR0: 8005003b CR2: 08076ac4 CR3: 37b34000 CR4: 00000690
> Call Trace:
>  [<c0237f28>] .text.lock.ip_conntrack_core+0x7d/0xd5
>  [<c023cf6d>] do_bindings+0x8d/0x260
>  [<c0238855>] try_rfc959+0x25/0x30
>  [<c0238dd7>] help+0x2f7/0x430
>  [<c0238830>] try_rfc959+0x0/0x30
>  [<c0238251>] tcp_packet+0xd1/0x160
>  [<c0236ea0>] ip_conntrack_in+0x100/0x220
>  [<c01fd182>] nf_iterate+0x72/0xb0
>  [<c0205fc0>] ip_rcv_finish+0x0/0x245
>  [<c01fd468>] nf_hook_slow+0x78/0x110
>  [<c0205fc0>] ip_rcv_finish+0x0/0x245
>  [<c0205da1>] ip_rcv+0x3c1/0x480
>  [<c0205fc0>] ip_rcv_finish+0x0/0x245
>  [<c01effe2>] alloc_skb+0x32/0xd0
>  [<c01f4d72>] netif_receive_skb+0x162/0x190
>  [<c01c9889>] e1000_clean_rx_irq+0x399/0x410
>  [<c01c9244>] e1000_clean+0x34/0xb0
>  [<c01f4f3f>] net_rx_action+0x7f/0x110
>  [<c011ae84>] __do_softirq+0xb4/0xc0
>  [<c0106b9c>] do_softirq+0x4c/0x60
>  =======================
>  [<c0106275>] do_IRQ+0x145/0x180
>  [<c010467c>] common_interrupt+0x18/0x20
>  [<c0101e20>] default_idle+0x0/0x40
>  [<c0101e4c>] default_idle+0x2c/0x40
>  [<c0101edb>] cpu_idle+0x3b/0x50
>  [<c01177b7>] __call_console_drivers+0x57/0x60
>  [<c01178af>] call_console_drivers+0x7f/0x100
> 
> 
> Lockup #2:
> Pid: 0, comm:              swapper
> EIP: 0060:[<c0261bd0>] CPU: 0
> EIP is at .text.lock.ip_nat_ftp+0x19/0x29
>  EFLAGS: 00000286    Not tainted  (2.6.6)
> EAX: 00000001 EBX: c0306000 ECX: d31c3034 EDX: eaeb8ac0
> ESI: 00000019 EDI: eaeb8a48 EBP: c0306d24 DS: 007b ES: 007b
> CR0: 8005003b CR2: 4024f0ec CR3: 31515000 CR4: 00000690
> Call Trace:
>  [<c0260592>] tcp_exp_matches_pkt+0x32/0x79
>  [<c0266e5f>] do_bindings+0x34f/0x570
>  [<c0264c17>] ip_nat_fn+0x77/0x310
>  [<c021f0be>] nf_iterate+0x6e/0xc0
>  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
>  [<c021f406>] nf_hook_slow+0x86/0x150
>  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
>  [<c022b8b3>] ip_finish_output+0x43/0x50
>  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
>  [<c022a47c>] ip_forward_finish+0x2c/0x50
>  [<c021f45a>] nf_hook_slow+0xda/0x150
>  [<c022a450>] ip_forward_finish+0x0/0x50
>  [<c022a3b7>] ip_forward+0x137/0x1d0
>  [<c022a450>] ip_forward_finish+0x0/0x50
>  [<c02290b8>] ip_rcv_finish+0x1e8/0x25d
>  [<c021f0be>] nf_iterate+0x6e/0xc0
>  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
>  [<c021f45a>] nf_hook_slow+0xda/0x150
>  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
>  [<c0228cad>] ip_rcv+0x18d/0x240
>  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
>  [<c0215a14>] netif_receive_skb+0x174/0x1a0
>  [<c01e60f8>] e1000_clean_rx_irq+0x3d8/0x490
>  [<c01e5a2c>] e1000_clean+0x3c/0xb0
>  [<c0215bf0>] net_rx_action+0x90/0x130
>  [<c011f204>] __do_softirq+0xb4/0xc0
>  [<c010764f>] do_softirq+0x4f/0x60
>  =======================
>  [<c0106979>] do_IRQ+0x1a9/0x260
>  [<c011091c>] smp_apic_timer_interrupt+0xcc/0x130
>  [<c0104bb0>] common_interrupt+0x18/0x20
>  [<c0102150>] default_idle+0x0/0x40
>  [<c010217f>] default_idle+0x2f/0x40
>  [<c010220b>] cpu_idle+0x3b/0x50
>  [<c02d7520>] unknown_bootoption+0x0/0x120
>  [<c02d7943>] start_kernel+0x173/0x1c0
>  [<c02d7520>] unknown_bootoption+0x0/0x120
> 
> 

Re: Deadlocks

[Phil Oester]

I agree I am likely experiencing the deadlock you refer to:

CPU1:
conntrack-helper:help: lock(private_lock)
ip_conntrack_expect_related: write_lock(ip_conntrack_lock)

CPU2:
nat-core:do_bindings: read_lock(ip_conntrack_lock)
nat-helper:help: lock(private_lock)

However, it's unclear to me that the ip_ftp_lock can be trivially eliminated.

This code path looks particularly prickly in ip_nat_ftp.c:

help
  ftp_data_fixup
    ip_conntrack_change_expect

so the nat helper is changing the expectation -- potentially at the same time
the conntrack helper is calling ip_conntrack_expect.  If the private lock
were removed, could this not cause a race condition if the expectation got
created just after the nat-helper changed the expectation?  

It seems the ip_ftp_lock is needed, but perhaps needs to be reworked to avoid
the deadlock condition illustrated above.

Thoughts?

Phil


On Sun, Jun 13, 2004 at 09:58:29PM +0200, Patrick McHardy wrote:
> On Wed, 2004-06-09 at 20:09, Phil Oester wrote:
> > For the past 3 months I've been experiencing deadlocks on some heavily
> > used gateway/firewall boxes which started after upgrading from 2.4.20.
> > 
> > I can confirm that moving back to 2.4.20 stops the hangs, moving to 2.4.21
> > (or any kernel after that) makes them return.  I am in the process of testing
> > out each individual 2.4.21-pre to find out where exactly the problem is.
> > 
> > In the interim, I've collected some SysRq output which may help in the
> > analysis.  Below are two separate lockups on a 2.6.6 kernel.  Anyone have
> > any bright ideas?
> 
> This looks like the problem I described a couple of month ago:
> http://lists.netfilter.org/pipermail/netfilter-devel/2003-November/013130.html
> I went through the 2.4.21 patch, but couldn't find anything that looks
> related to this. The patch attached to the email above should apply to
> something around 2.4.23. Please also enable CONFIG_NETFILTER_DEBUG, so
> we can see where exactly the problem occurs.
> 
> Regards
> Patrick
> 
> > 
> > Phil Oester
> > 
> > 
> > Lockup #1:
> > Pid: 0, comm:              swapper
> > EIP: 0060:[<c024a3e7>] CPU: 1
> > EIP is at __write_lock_failed+0xf/0x20
> >  EFLAGS: 00000287    Not tainted  (2.6.6)
> > EAX: c0283360 EBX: ffffffff ECX: 7d9d14aa EDX: ee83c1e0
> > ESI: f454b910 EDI: ffffffff EBP: 0000007d DS: 007b ES: 007b
> > CR0: 8005003b CR2: 08076ac4 CR3: 37b34000 CR4: 00000690
> > Call Trace:
> >  [<c0237f28>] .text.lock.ip_conntrack_core+0x7d/0xd5
> >  [<c023cf6d>] do_bindings+0x8d/0x260
> >  [<c0238855>] try_rfc959+0x25/0x30
> >  [<c0238dd7>] help+0x2f7/0x430
> >  [<c0238830>] try_rfc959+0x0/0x30
> >  [<c0238251>] tcp_packet+0xd1/0x160
> >  [<c0236ea0>] ip_conntrack_in+0x100/0x220
> >  [<c01fd182>] nf_iterate+0x72/0xb0
> >  [<c0205fc0>] ip_rcv_finish+0x0/0x245
> >  [<c01fd468>] nf_hook_slow+0x78/0x110
> >  [<c0205fc0>] ip_rcv_finish+0x0/0x245
> >  [<c0205da1>] ip_rcv+0x3c1/0x480
> >  [<c0205fc0>] ip_rcv_finish+0x0/0x245
> >  [<c01effe2>] alloc_skb+0x32/0xd0
> >  [<c01f4d72>] netif_receive_skb+0x162/0x190
> >  [<c01c9889>] e1000_clean_rx_irq+0x399/0x410
> >  [<c01c9244>] e1000_clean+0x34/0xb0
> >  [<c01f4f3f>] net_rx_action+0x7f/0x110
> >  [<c011ae84>] __do_softirq+0xb4/0xc0
> >  [<c0106b9c>] do_softirq+0x4c/0x60
> >  =======================
> >  [<c0106275>] do_IRQ+0x145/0x180
> >  [<c010467c>] common_interrupt+0x18/0x20
> >  [<c0101e20>] default_idle+0x0/0x40
> >  [<c0101e4c>] default_idle+0x2c/0x40
> >  [<c0101edb>] cpu_idle+0x3b/0x50
> >  [<c01177b7>] __call_console_drivers+0x57/0x60
> >  [<c01178af>] call_console_drivers+0x7f/0x100
> > 
> > 
> > Lockup #2:
> > Pid: 0, comm:              swapper
> > EIP: 0060:[<c0261bd0>] CPU: 0
> > EIP is at .text.lock.ip_nat_ftp+0x19/0x29
> >  EFLAGS: 00000286    Not tainted  (2.6.6)
> > EAX: 00000001 EBX: c0306000 ECX: d31c3034 EDX: eaeb8ac0
> > ESI: 00000019 EDI: eaeb8a48 EBP: c0306d24 DS: 007b ES: 007b
> > CR0: 8005003b CR2: 4024f0ec CR3: 31515000 CR4: 00000690
> > Call Trace:
> >  [<c0260592>] tcp_exp_matches_pkt+0x32/0x79
> >  [<c0266e5f>] do_bindings+0x34f/0x570
> >  [<c0264c17>] ip_nat_fn+0x77/0x310
> >  [<c021f0be>] nf_iterate+0x6e/0xc0
> >  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
> >  [<c021f406>] nf_hook_slow+0x86/0x150
> >  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
> >  [<c022b8b3>] ip_finish_output+0x43/0x50
> >  [<c022dcb0>] ip_finish_output2+0x0/0x1cb
> >  [<c022a47c>] ip_forward_finish+0x2c/0x50
> >  [<c021f45a>] nf_hook_slow+0xda/0x150
> >  [<c022a450>] ip_forward_finish+0x0/0x50
> >  [<c022a3b7>] ip_forward+0x137/0x1d0
> >  [<c022a450>] ip_forward_finish+0x0/0x50
> >  [<c02290b8>] ip_rcv_finish+0x1e8/0x25d
> >  [<c021f0be>] nf_iterate+0x6e/0xc0
> >  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
> >  [<c021f45a>] nf_hook_slow+0xda/0x150
> >  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
> >  [<c0228cad>] ip_rcv+0x18d/0x240
> >  [<c0228ed0>] ip_rcv_finish+0x0/0x25d
> >  [<c0215a14>] netif_receive_skb+0x174/0x1a0
> >  [<c01e60f8>] e1000_clean_rx_irq+0x3d8/0x490
> >  [<c01e5a2c>] e1000_clean+0x3c/0xb0
> >  [<c0215bf0>] net_rx_action+0x90/0x130
> >  [<c011f204>] __do_softirq+0xb4/0xc0
> >  [<c010764f>] do_softirq+0x4f/0x60
> >  =======================
> >  [<c0106979>] do_IRQ+0x1a9/0x260
> >  [<c011091c>] smp_apic_timer_interrupt+0xcc/0x130
> >  [<c0104bb0>] common_interrupt+0x18/0x20
> >  [<c0102150>] default_idle+0x0/0x40
> >  [<c010217f>] default_idle+0x2f/0x40
> >  [<c010220b>] cpu_idle+0x3b/0x50
> >  [<c02d7520>] unknown_bootoption+0x0/0x120
> >  [<c02d7943>] start_kernel+0x173/0x1c0
> >  [<c02d7520>] unknown_bootoption+0x0/0x120
> > 
> > 
> 
> 

Re: Deadlocks

[Patrick McHardy]

[-- Attachment #1: Type: text/plain, Size: 1531 bytes --]

Phil Oester wrote:
> I agree I am likely experiencing the deadlock you refer to:
> 
> CPU1:
> conntrack-helper:help: lock(private_lock)
> ip_conntrack_expect_related: write_lock(ip_conntrack_lock)
> 
> CPU2:
> nat-core:do_bindings: read_lock(ip_conntrack_lock)
> nat-helper:help: lock(private_lock)
> 
> However, it's unclear to me that the ip_ftp_lock can be trivially eliminated.
> 
> This code path looks particularly prickly in ip_nat_ftp.c:
> 
> help
>   ftp_data_fixup
>     ip_conntrack_change_expect
> 
> so the nat helper is changing the expectation -- potentially at the same time
> the conntrack helper is calling ip_conntrack_expect.  If the private lock
> were removed, could this not cause a race condition if the expectation got
> created just after the nat-helper changed the expectation?  

I don't understand what you mean. The nat-helper can not change the
expectation before it's created, and once it's created it can not
be touched by the conntrack helper anymore. ip_ftp_lock is protecting
ftp_buffer and ct_ftp_info, so it can be dropped directly after the
call to find_pattern. The help function in the nat_helper only touches
the expectation, which is protected by ip_conntrack_lock, so it doesn't
need ip_ftp_lock lock at all.

> 
> It seems the ip_ftp_lock is needed, but perhaps needs to be reworked to avoid
> the deadlock condition illustrated above.

I've attached an untested patch which should fix this problem for the
ftp helper. Care to give it a try ?

Regards
Patrick

> 
> Thoughts?
> 
> Phil

[-- Attachment #2: x --]
[-- Type: text/plain, Size: 4945 bytes --]

===== include/linux/netfilter_ipv4/ip_conntrack_ftp.h 1.4 vs edited =====
--- 1.4/include/linux/netfilter_ipv4/ip_conntrack_ftp.h	2002-08-19 20:41:51 +02:00
+++ edited/include/linux/netfilter_ipv4/ip_conntrack_ftp.h	2004-06-15 08:20:59 +02:00
@@ -4,11 +4,6 @@
 
 #ifdef __KERNEL__
 
-#include <linux/netfilter_ipv4/lockhelp.h>
-
-/* Protects ftp part of conntracks */
-DECLARE_LOCK_EXTERN(ip_ftp_lock);
-
 #define FTP_PORT	21
 
 #endif /* __KERNEL__ */
===== net/ipv4/netfilter/ip_conntrack_ftp.c 1.19 vs edited =====
--- 1.19/net/ipv4/netfilter/ip_conntrack_ftp.c	2004-03-30 06:18:56 +02:00
+++ edited/net/ipv4/netfilter/ip_conntrack_ftp.c	2004-06-15 08:20:28 +02:00
@@ -27,7 +27,7 @@
 /* This is slow, but it's simple. --RR */
 static char ftp_buffer[65536];
 
-DECLARE_LOCK(ip_ftp_lock);
+static DECLARE_LOCK(ip_ftp_lock);
 struct module *ip_conntrack_ftp = THIS_MODULE;
 
 #define MAX_PORTS 8
@@ -327,6 +327,7 @@
 				     search[i].getnum);
 		if (found) break;
 	}
+	UNLOCK_BH(&ip_ftp_lock);
 	if (found == -1) {
 		/* We don't usually drop packets.  After all, this is
 		   connection tracking, not packet filtering.
@@ -336,12 +337,9 @@
 			printk("conntrack_ftp: partial %s %u+%u\n",
 			       search[i].pattern,
 			       ntohl(tcph.seq), datalen);
-		ret = NF_DROP;
-		goto out;
-	} else if (found == 0) { /* No match */
-		ret = NF_ACCEPT;
-		goto out;
-	}
+		return NF_DROP;
+	} else if (found == 0) /* No match */
+		return NF_ACCEPT;
 
 	DEBUGP("conntrack_ftp: match `%.*s' (%u bytes at %u)\n",
 	       (int)matchlen, data + matchoff,
@@ -349,11 +347,8 @@
 
 	/* Allocate expectation which will be inserted */
 	exp = ip_conntrack_expect_alloc();
-	if (exp == NULL) {
-		ret = NF_ACCEPT;
-		goto out;
-	}
-
+	if (exp == NULL)
+		return NF_ACCEPT;
 	exp_ftp_info = &exp->help.exp_ftp_info;
 
 	/* Update the ftp info */
@@ -376,10 +371,8 @@
 		   <lincoln@cesar.org.br> for reporting this potential
 		   problem (DMZ machines opening holes to internal
 		   networks, or the packet filter itself). */
-		if (!loose) {
-			ret = NF_ACCEPT;
-			goto out;
-		}
+		if (!loose)
+			return NF_ACCEPT;
 	}
 
 	exp->tuple = ((struct ip_conntrack_tuple)
@@ -397,7 +390,8 @@
 
 	/* Ignore failure; should only happen with NAT */
 	ip_conntrack_expect_related(exp, ct);
-	ret = NF_ACCEPT;
+	return NF_ACCEPT;
+
  out:
 	UNLOCK_BH(&ip_ftp_lock);
 	return ret;
@@ -457,7 +451,6 @@
 }
 
 PROVIDES_CONNTRACK(ftp);
-EXPORT_SYMBOL(ip_ftp_lock);
 
 module_init(init);
 module_exit(fini);
===== net/ipv4/netfilter/ip_nat_ftp.c 1.13 vs edited =====
--- 1.13/net/ipv4/netfilter/ip_nat_ftp.c	2004-01-29 00:59:33 +01:00
+++ edited/net/ipv4/netfilter/ip_nat_ftp.c	2004-06-15 08:23:13 +02:00
@@ -37,8 +37,6 @@
 MODULE_PARM(ports, "1-" __MODULE_STRING(MAX_PORTS) "i");
 #endif
 
-DECLARE_LOCK_EXTERN(ip_ftp_lock);
-
 /* FIXME: Time out? --RR */
 
 static unsigned int
@@ -61,8 +59,6 @@
 	DEBUGP("nat_expected: We have a connection!\n");
 	exp_ftp_info = &ct->master->help.exp_ftp_info;
 
-	LOCK_BH(&ip_ftp_lock);
-
 	if (exp_ftp_info->ftptype == IP_CT_FTP_PORT
 	    || exp_ftp_info->ftptype == IP_CT_FTP_EPRT) {
 		/* PORT command: make connection go to the client. */
@@ -77,7 +73,6 @@
 		DEBUGP("nat_expected: PASV cmd. %u.%u.%u.%u->%u.%u.%u.%u\n",
 		       NIPQUAD(newsrcip), NIPQUAD(newdstip));
 	}
-	UNLOCK_BH(&ip_ftp_lock);
 
 	if (HOOK2MANIP(hooknum) == IP_NAT_MANIP_SRC)
 		newip = newsrcip;
@@ -113,8 +108,6 @@
 {
 	char buffer[sizeof("nnn,nnn,nnn,nnn,nnn,nnn")];
 
-	MUST_BE_LOCKED(&ip_ftp_lock);
-
 	sprintf(buffer, "%u,%u,%u,%u,%u,%u",
 		NIPQUAD(newip), port>>8, port&0xFF);
 
@@ -136,8 +129,6 @@
 {
 	char buffer[sizeof("|1|255.255.255.255|65535|")];
 
-	MUST_BE_LOCKED(&ip_ftp_lock);
-
 	sprintf(buffer, "|1|%u.%u.%u.%u|%u|", NIPQUAD(newip), port);
 
 	DEBUGP("calling ip_nat_mangle_tcp_packet\n");
@@ -158,8 +149,6 @@
 {
 	char buffer[sizeof("|||65535|")];
 
-	MUST_BE_LOCKED(&ip_ftp_lock);
-
 	sprintf(buffer, "|||%u|", port);
 
 	DEBUGP("calling ip_nat_mangle_tcp_packet\n");
@@ -191,7 +180,6 @@
 	u_int16_t port;
 	struct ip_conntrack_tuple newtuple;
 
-	MUST_BE_LOCKED(&ip_ftp_lock);
 	DEBUGP("FTP_NAT: seq %u + %u in %u\n",
 	       expect->seq, ct_ftp_info->len,
 	       ntohl(tcph->seq));
@@ -270,15 +258,12 @@
 	}
 
 	datalen = (*pskb)->len - iph->ihl * 4 - tcph->doff * 4;
-	LOCK_BH(&ip_ftp_lock);
 	/* If it's in the right range... */
 	if (between(exp->seq + ct_ftp_info->len,
 		    ntohl(tcph->seq),
 		    ntohl(tcph->seq) + datalen)) {
-		if (!ftp_data_fixup(ct_ftp_info, ct, pskb, ctinfo, exp)) {
-			UNLOCK_BH(&ip_ftp_lock);
+		if (!ftp_data_fixup(ct_ftp_info, ct, pskb, ctinfo, exp))
 			return NF_DROP;
-		}
 	} else {
 		/* Half a match?  This means a partial retransmisison.
 		   It's a cracker being funky. */
@@ -288,11 +273,8 @@
 			       ntohl(tcph->seq),
 			       ntohl(tcph->seq) + datalen);
 		}
-		UNLOCK_BH(&ip_ftp_lock);
 		return NF_DROP;
 	}
-	UNLOCK_BH(&ip_ftp_lock);
-
 	return NF_ACCEPT;
 }
 

Re: Deadlocks

[Phil Oester]

Yes, my statement was not clear at all.  What I meant was something like:

cpu 1:
  conntrack helper calls ip_conntrack_expect_related

cpu 2:
  nat helper calls ip_conntrack_change_expect

CPU 2 ends up causing a duplicate expectation, because the nat helper
changed the expectation to match the one created by cpu 1.

I do see duplicate expectations occasionally:

# grep EXP /proc/net/ip_conntrack 
EXPECTING: - use=1 proto=6 src=10.20.116.197 dst=10.20.153.248 sport=0 dport=4309 
EXPECTING: - use=1 proto=6 src=10.20.116.197 dst=10.20.153.248 sport=0 dport=4309 

which may or may not be related to the above.

In any event, I have applied your patch to 2.6.7, and am running it.  Typically
the box would not last more than a couple days, so I'll let you know what 
happens.

Phil

On Tue, Jun 15, 2004 at 08:23:26AM +0200, Patrick McHardy wrote:
> Phil Oester wrote:
> >so the nat helper is changing the expectation -- potentially at the same 
> >time
> >the conntrack helper is calling ip_conntrack_expect.  If the private lock
> >were removed, could this not cause a race condition if the expectation got
> >created just after the nat-helper changed the expectation?  
> 
> I don't understand what you mean. The nat-helper can not change the
> expectation before it's created, and once it's created it can not
> be touched by the conntrack helper anymore. ip_ftp_lock is protecting
> ftp_buffer and ct_ftp_info, so it can be dropped directly after the
> call to find_pattern. The help function in the nat_helper only touches
> the expectation, which is protected by ip_conntrack_lock, so it doesn't
> need ip_ftp_lock lock at all.

Re: Deadlocks

[Patrick McHardy]

Phil Oester wrote:
> Yes, my statement was not clear at all.  What I meant was something like:
> 
> cpu 1:
>   conntrack helper calls ip_conntrack_expect_related
> 
> cpu 2:
>   nat helper calls ip_conntrack_change_expect
> 
> CPU 2 ends up causing a duplicate expectation, because the nat helper
> changed the expectation to match the one created by cpu 1.

This can't happen because ip_conntrack_change_expect in is called under
read_locked ip_conntrack_lock and checks for duplicates and
ip_conntrack_expect_related write_locks ip_conntrack_lock and checks
for duplicates. ip_conntrack_change_expect additionally write_locks
ip_conntrack_expect_tuple_lock so it won't race with itself on another
CPU.

> 
> I do see duplicate expectations occasionally:
> 
> # grep EXP /proc/net/ip_conntrack 
> EXPECTING: - use=1 proto=6 src=10.20.116.197 dst=10.20.153.248 sport=0 dport=4309 
> EXPECTING: - use=1 proto=6 src=10.20.116.197 dst=10.20.153.248 sport=0 dport=4309 
> 
> which may or may not be related to the above.

Probably not, unless I missed something. I'm going to see if I can find
something else.

> 
> In any event, I have applied your patch to 2.6.7, and am running it.  Typically
> the box would not last more than a couple days, so I'll let you know what 
> happens.

Great, I'm really interested ..

Regards
Patrick

> 
> Phil
> 

Re: Deadlocks

[Phil Oester]

Well, it lasted about 36 hours -- not much longer than usual.  Unfortunately,
the stack appears to have been corrupted, so I can't get a decent backtrace.
Here is what I could get off of SysRQ-P:

Pid: 0, comm:              swapper
EIP: 0060:[<c0258b15>] CPU: 1
EIP is at tcp_find_option+0x55/0xa0
 EFLAGS: 00000203    Not tainted  (2.6.7)
EAX: 000000fe EBX: 00000040 ECX: 00000002 EDX: 00000034
ESI: 00000018 EDI: f89c39bc EBP: 00000000 DS: 007b ES: 007b
CR0: 8005003b CR2: 080da0b4 CR3: 379cc000 CR4: 000006d0
Stack pointer is garbage, not printing trace

Perhaps of interest, not sure, but the FTP server at 10.0.16.197 frequently
shows duplicate expectations, as shown below shortly after rebooting:

EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 
EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 
EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 

Unless you've got any other ideas, may have to revert this box to non-SMP
so I can have a peaceful weekend ;-)

Phil


On Thu, Jun 17, 2004 at 06:20:15PM +0200, Patrick McHardy wrote:
> Phil Oester wrote:
> >In any event, I have applied your patch to 2.6.7, and am running it.  
> >Typically
> >the box would not last more than a couple days, so I'll let you know what 
> >happens.
> 
> Great, I'm really interested ..

Re: Deadlocks

[Patrick McHardy]

Phil Oester wrote:
> Well, it lasted about 36 hours -- not much longer than usual.  Unfortunately,
> the stack appears to have been corrupted, so I can't get a decent backtrace.
> Here is what I could get off of SysRQ-P:
> 
> Pid: 0, comm:              swapper
> EIP: 0060:[<c0258b15>] CPU: 1
> EIP is at tcp_find_option+0x55/0xa0
>  EFLAGS: 00000203    Not tainted  (2.6.7)
> EAX: 000000fe EBX: 00000040 ECX: 00000002 EDX: 00000034
> ESI: 00000018 EDI: f89c39bc EBP: 00000000 DS: 007b ES: 007b
> CR0: 8005003b CR2: 080da0b4 CR3: 379cc000 CR4: 000006d0
> Stack pointer is garbage, not printing trace
> 
> Perhaps of interest, not sure, but the FTP server at 10.0.16.197 frequently
> shows duplicate expectations, as shown below shortly after rebooting:
> 
> EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 
> EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 
> EXPECTING: - use=1 proto=6 src=10.0.16.197 dst=10.0.53.248 sport=0 dport=4353 

Not sure either, but it's a start. Have you tried running the box with
netfilter debugging enabled ? Please also apply the ip_nf_assert fix
from pom-ng, otherwise CONFIG_NETFILTER_DEBUG won't help much.
BTW: Is the box a router or is conntrack running on the FTP server
itself ?

> Unless you've got any other ideas, may have to revert this box to non-SMP
> so I can have a peaceful weekend ;-)

No more ideas currently .. ;(

> Phil
> 

Regards
Patrick

Re: Deadlocks

[Phil Oester]

On Mon, Jun 21, 2004 at 02:46:19AM +0200, Patrick McHardy wrote:
> Not sure either, but it's a start. Have you tried running the box with
> netfilter debugging enabled ? Please also apply the ip_nf_assert fix
> from pom-ng, otherwise CONFIG_NETFILTER_DEBUG won't help much.
> BTW: Is the box a router or is conntrack running on the FTP server
> itself ?

The box is a router -- the ftp server is a separate box.

Thanks for the tip on the ip_nf_assert patch - I'd been running with debugging
enabled but wondered why I never saw anything...

Now that I enabled debugging (for real), I hit this one a few hundred times
per minute:

NF_IP_ASSERT: net/ipv4/netfilter/ip_conntrack_core.c:717(init_conntrack)

which is in this chunk of code:

        if (expected) {
                DEBUGP("conntrack: expectation arrives ct=%p exp=%p\n",
                        conntrack, expected);
                /* Welcome, Mr. Bond.  We've been expecting you... */
                IP_NF_ASSERT(master_ct(conntrack));
                __set_bit(IPS_EXPECTED_BIT, &conntrack->status);
                conntrack->master = expected;
                expected->sibling = conntrack;
                LIST_DELETE(&ip_conntrack_expect_list, expected);
                expected->expectant->expecting--;
                nf_conntrack_get(&master_ct(conntrack)->infos[0]);
        }


Other than being mildly annoying, this doesn't explain the deadlocks,
so I'll let it run for a few more days...

Phil

Re: Deadlocks

[Patrick McHardy]

Phil Oester wrote:

> Thanks for the tip on the ip_nf_assert patch - I'd been running with debugging
> enabled but wondered why I never saw anything...
> 
> Now that I enabled debugging (for real), I hit this one a few hundred times
> per minute:
> 
> NF_IP_ASSERT: net/ipv4/netfilter/ip_conntrack_core.c:717(init_conntrack)

Yes, this assertion is bogus, I need to update the patch in pom-ng.
Just delete the ASSERTION, it tests for conntrack->master, which is
assigned two lines below.

Hopefully we get to see something more interesting ..

Regards
Patrick

Re: Deadlocks

[Phil Oester]

Well, the box has now lasted 7 days without a deadlock, so I'd venture
to say your patch has solved the issue, and should probably be added to
mainline.

Thanks for the help

Phil

On Mon, Jun 21, 2004 at 02:46:19AM +0200, Patrick McHardy wrote:
> Not sure either, but it's a start. Have you tried running the box with
> netfilter debugging enabled ? Please also apply the ip_nf_assert fix
> from pom-ng, otherwise CONFIG_NETFILTER_DEBUG won't help much.
> BTW: Is the box a router or is conntrack running on the FTP server
> itself ?
> 
> >Unless you've got any other ideas, may have to revert this box to non-SMP
> >so I can have a peaceful weekend ;-)
> 
> No more ideas currently .. ;(

Re: Deadlocks

[Patrick McHardy]

Phil Oester wrote:
> Well, the box has now lasted 7 days without a deadlock, so I'd venture
> to say your patch has solved the issue, and should probably be added to
> mainline.

Thanks for the update, but I thought it kept crashing when you first
tried the patch ?

Regards
Patrick

> 
> Thanks for the help
> 
> Phil

Re: Deadlocks

[Phil Oester]

On Tue, Jun 29, 2004 at 08:00:45PM +0200, Patrick McHardy wrote:
> Phil Oester wrote:
> >Well, the box has now lasted 7 days without a deadlock, so I'd venture
> >to say your patch has solved the issue, and should probably be added to
> >mainline.
> 
> Thanks for the update, but I thought it kept crashing when you first
> tried the patch ?

It crashed once, but appears to have been stack corruption which
could've been caused by anything.  After it crashed I enabled
CONFIG_NETFILTER_DEBUG and it's been quiet ever since.  Possible
that enabling debugging prevents the issue?

Phil

Re: Deadlocks

[Patrick McHardy]

Phil Oester wrote:
> On Tue, Jun 29, 2004 at 08:00:45PM +0200, Patrick McHardy wrote:
>>
>>Thanks for the update, but I thought it kept crashing when you first
>>tried the patch ?
> 
> It crashed once, but appears to have been stack corruption which
> could've been caused by anything.  After it crashed I enabled
> CONFIG_NETFILTER_DEBUG and it's been quiet ever since.  Possible
> that enabling debugging prevents the issue?

Could be, but I doubt it. Could you try without CONFIG_NETFILTER_DEBUG
once more ?

Regards
Patrick

> 
> Phil
> 

Re: Deadlocks

[Phil Oester]

On Wed, Jun 30, 2004 at 11:50:50AM +0200, Patrick McHardy wrote:
> Could be, but I doubt it. Could you try without CONFIG_NETFILTER_DEBUG
> once more ?

Interestingly, when it crashed that one time it was in tcp_find_option,
and I had a uniprocessor box hang in tcp_find_option yesterday also.  It
looks like I'm hitting the infinite loop discussed here:

http://www.netfilter.org/security/2004-06-30-2.6-tcpoption.html

since I have 2 tcp-option rules:

$IPT -A badtcp -p tcp --tcp-option 64 -j logdrop
$IPT -A badtcp -p tcp --tcp-option 128 -j logdrop

So I'll apply that patch along with your FTP locking patch and see how
it works out.

Phil