2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

[Rafael J. Wysocki]

Hi,

I've got the following BUG on Asus L5D (x86-64) with the 2.6.13-rc5-mm1 kernel:

BUG: rwlock recursion on CPU#0, nscd/3668, ffffffff8817d4a0

Call Trace:<ffffffff80241ca9>{add_preempt_count+105} <ffffffff80241682>{rwlock_bug+114}
       <ffffffff8024179e>{_raw_write_lock+62} <ffffffff80350f48>{_write_lock_bh+40}
       <ffffffff88171824>{:ip_conntrack:destroy_conntrack+196}
       <ffffffff88170435>{:ip_conntrack:__ip_ct_event_cache_init+165}
       <ffffffff88170549>{:ip_conntrack:ip_ct_refresh_acct+249}
       <ffffffff88173c4f>{:ip_conntrack:udp_packet+47} <ffffffff88172143>{:ip_conntrack:ip_conntrack_in+1059}
       <ffffffff8816fb4c>{:ip_conntrack:ip_conntrack_local+76}
       <ffffffff802fe7ec>{nf_iterate+92} <ffffffff80311d90>{dst_output+0}
       <ffffffff802ff3de>{nf_hook_slow+142} <ffffffff80311d90>{dst_output+0}
       <ffffffff803123bf>{ip_push_pending_frames+895} <ffffffff802eade9>{lock_sock+201}
       <ffffffff8032e72e>{udp_push_pending_frames+574} <ffffffff8032ffc7>{udp_sendmsg+1703}
       <ffffffff8013874e>{current_fs_time+78} <ffffffff8015c03c>{file_read_actor+60}
       <ffffffff80199b6c>{update_atime+76} <ffffffff8015e8fa>{do_generic_mapping_read+1194}
       <ffffffff80335946>{inet_sendmsg+86} <ffffffff802e7dff>{sock_sendmsg+271}
       <ffffffff80241ca9>{add_preempt_count+105} <ffffffff8016153e>{free_hot_cold_page+270}
       <ffffffff801615bb>{free_hot_page+11} <ffffffff80241ca9>{add_preempt_count+105}
       <ffffffff8014a670>{autoremove_wake_function+0} <ffffffff802e846c>{sockfd_lookup+28}
       <ffffffff802e9c64>{sys_sendto+260} <ffffffff80193003>{do_sys_poll+851}
       <ffffffff80193de0>{__pollwait+0} <ffffffff8010eb3e>{system_call+126}
       
---------------------------
| preempt count: 00000303 ]
| 3 level deep critical section nesting:
----------------------------------------
.. [<ffffffff802ff385>] .... nf_hook_slow+0x35/0x160
.....[<ffffffff803123bf>] ..   ( <= ip_push_pending_frames+0x37f/0x490)
.. [<ffffffff80350f40>] .... _write_lock_bh+0x20/0x30
.....[<ffffffff88170500>] ..   ( <= ip_ct_refresh_acct+0xb0/0x160 [ip_conntrack])
.. [<ffffffff80350f40>] .... _write_lock_bh+0x20/0x30
.....[<ffffffff88171824>] ..   ( <= destroy_conntrack+0xc4/0x180 [ip_conntrack])

It does not seem to be easily reproducible.

Greets,
Rafael


-- 
- Would you tell me, please, which way I ought to go from here?
- That depends a good deal on where you want to get to.
		-- Lewis Carroll "Alice's Adventures in Wonderland"

Re: 2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

[Patrick McHardy]

Rafael J. Wysocki wrote:
> I've got the following BUG on Asus L5D (x86-64) with the 2.6.13-rc5-mm1 kernel:
> 
> BUG: rwlock recursion on CPU#0, nscd/3668, ffffffff8817d4a0
> 
> Call Trace:<ffffffff80241ca9>{add_preempt_count+105} <ffffffff80241682>{rwlock_bug+114}
>        <ffffffff8024179e>{_raw_write_lock+62} <ffffffff80350f48>{_write_lock_bh+40}
>        <ffffffff88171824>{:ip_conntrack:destroy_conntrack+196}
>        <ffffffff88170435>{:ip_conntrack:__ip_ct_event_cache_init+165}
>        <ffffffff88170549>{:ip_conntrack:ip_ct_refresh_acct+249}
>        <ffffffff88173c4f>{:ip_conntrack:udp_packet+47} <ffffffff88172143>{:ip_conntrack:ip_conntrack_in+1059}
>        <ffffffff8816fb4c>{:ip_conntrack:ip_conntrack_local+76}
>        <ffffffff802fe7ec>{nf_iterate+92} <ffffffff80311d90>{dst_output+0}
>        <ffffffff802ff3de>{nf_hook_slow+142} <ffffffff80311d90>{dst_output+0}
>        <ffffffff803123bf>{ip_push_pending_frames+895} <ffffffff802eade9>{lock_sock+201}
>        <ffffffff8032e72e>{udp_push_pending_frames+574} <ffffffff8032ffc7>{udp_sendmsg+1703}
>        <ffffffff8013874e>{current_fs_time+78} <ffffffff8015c03c>{file_read_actor+60}
>        <ffffffff80199b6c>{update_atime+76} <ffffffff8015e8fa>{do_generic_mapping_read+1194}
>        <ffffffff80335946>{inet_sendmsg+86} <ffffffff802e7dff>{sock_sendmsg+271}
>        <ffffffff80241ca9>{add_preempt_count+105} <ffffffff8016153e>{free_hot_cold_page+270}
>        <ffffffff801615bb>{free_hot_page+11} <ffffffff80241ca9>{add_preempt_count+105}
>        <ffffffff8014a670>{autoremove_wake_function+0} <ffffffff802e846c>{sockfd_lookup+28}
>        <ffffffff802e9c64>{sys_sendto+260} <ffffffff80193003>{do_sys_poll+851}
>        <ffffffff80193de0>{__pollwait+0} <ffffffff8010eb3e>{system_call+126}

I fear my event cache fixes are responsible for this, we must not cache
events while holding a lock anymore because we might need to deliver
old cached events. I'll try to come up with a fix later.

Re: 2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

[Zwane Mwaikambo]

On Sun, 14 Aug 2005, Rafael J. Wysocki wrote:

> I've got the following BUG on Asus L5D (x86-64) with the 2.6.13-rc5-mm1 kernel:
> 
> BUG: rwlock recursion on CPU#0, nscd/3668, ffffffff8817d4a0
> 
> Call Trace:<ffffffff80241ca9>{add_preempt_count+105} <ffffffff80241682>{rwlock_bug+114}
>        <ffffffff8024179e>{_raw_write_lock+62} <ffffffff80350f48>{_write_lock_bh+40}
>        <ffffffff88171824>{:ip_conntrack:destroy_conntrack+196}
>        <ffffffff88170435>{:ip_conntrack:__ip_ct_event_cache_init+165}
>        <ffffffff88170549>{:ip_conntrack:ip_ct_refresh_acct+249}
>        <ffffffff88173c4f>{:ip_conntrack:udp_packet+47} <ffffffff88172143>{:ip_conntrack:ip_conntrack_in+1059}
>        <ffffffff8816fb4c>{:ip_conntrack:ip_conntrack_local+76}
>        <ffffffff802fe7ec>{nf_iterate+92} <ffffffff80311d90>{dst_output+0}
>        <ffffffff802ff3de>{nf_hook_slow+142} <ffffffff80311d90>{dst_output+0}
>        <ffffffff803123bf>{ip_push_pending_frames+895} <ffffffff802eade9>{lock_sock+201}
>        <ffffffff8032e72e>{udp_push_pending_frames+574} <ffffffff8032ffc7>{udp_sendmsg+1703}
>        <ffffffff8013874e>{current_fs_time+78} <ffffffff8015c03c>{file_read_actor+60}
>        <ffffffff80199b6c>{update_atime+76} <ffffffff8015e8fa>{do_generic_mapping_read+1194}
>        <ffffffff80335946>{inet_sendmsg+86} <ffffffff802e7dff>{sock_sendmsg+271}
>        <ffffffff80241ca9>{add_preempt_count+105} <ffffffff8016153e>{free_hot_cold_page+270}
>        <ffffffff801615bb>{free_hot_page+11} <ffffffff80241ca9>{add_preempt_count+105}
>        <ffffffff8014a670>{autoremove_wake_function+0} <ffffffff802e846c>{sockfd_lookup+28}
>        <ffffffff802e9c64>{sys_sendto+260} <ffffffff80193003>{do_sys_poll+851}
>        <ffffffff80193de0>{__pollwait+0} <ffffffff8010eb3e>{system_call+126}
>        
> ---------------------------
> | preempt count: 00000303 ]
> | 3 level deep critical section nesting:
> ----------------------------------------
> .. [<ffffffff802ff385>] .... nf_hook_slow+0x35/0x160
> .....[<ffffffff803123bf>] ..   ( <= ip_push_pending_frames+0x37f/0x490)
> .. [<ffffffff80350f40>] .... _write_lock_bh+0x20/0x30
> .....[<ffffffff88170500>] ..   ( <= ip_ct_refresh_acct+0xb0/0x160 [ip_conntrack])
> .. [<ffffffff80350f40>] .... _write_lock_bh+0x20/0x30
> .....[<ffffffff88171824>] ..   ( <= destroy_conntrack+0xc4/0x180 [ip_conntrack])

Is the following patch correct? ip_conntrack_event_cache should never be 
called with ip_conntrack_lock held and ct_add_counters does not need to be 
called with ip_conntrack_lock held.

Index: linux-2.6.13-rc5-mm1/net/ipv4/netfilter/ip_conntrack_core.c
===================================================================
RCS file: /home/cvsroot/linux-2.6.13-rc5-mm1/net/ipv4/netfilter/ip_conntrack_core.c,v
retrieving revision 1.1.1.1
diff -u -p -B -r1.1.1.1 ip_conntrack_core.c
--- linux-2.6.13-rc5-mm1/net/ipv4/netfilter/ip_conntrack_core.c	7 Aug 2005 21:38:40 -0000	1.1.1.1
+++ linux-2.6.13-rc5-mm1/net/ipv4/netfilter/ip_conntrack_core.c	15 Aug 2005 02:09:23 -0000
@@ -1139,15 +1139,20 @@ void ip_ct_refresh_acct(struct ip_conntr
 		ct->timeout.expires = extra_jiffies;
 		ct_add_counters(ct, ctinfo, skb);
 	} else {
+		int do_event_cache = 0;
+
 		write_lock_bh(&ip_conntrack_lock);
 		/* Need del_timer for race avoidance (may already be dying). */
 		if (del_timer(&ct->timeout)) {
 			ct->timeout.expires = jiffies + extra_jiffies;
 			add_timer(&ct->timeout);
-			ip_conntrack_event_cache(IPCT_REFRESH, skb);
+			do_event_cache = 1;
 		}
-		ct_add_counters(ct, ctinfo, skb);
 		write_unlock_bh(&ip_conntrack_lock);
+
+		if (do_event_cache)
+			ip_conntrack_event_cache(IPCT_REFRESH, skb);
+		ct_add_counters(ct, ctinfo, skb);
 	}
 }
 

Re: 2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

[Harald Welte]

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

On Sun, Aug 14, 2005 at 08:15:53PM -0600, Zwane Mwaikambo wrote:

> Is the following patch correct? ip_conntrack_event_cache should never be 
> called with ip_conntrack_lock held and ct_add_counters does not need to be 
> called with ip_conntrack_lock held.

No, it's not correct.  ct_add_countes has to be called from within
write_lock_bh() on ip_conntrack_lock.

So if you keep the ct_add_counters() call where it is and only apply the
rest of your patch (i.e. deferring of ip_conntrack_event_cache() call),
then I think your patch would work.

However, the whole eventcache needs to be audited, it's called from a
number of places.

As Patrick wrote he's working on a solution, I'm not going to intervene
or replicate his work.  As a interim solution I'd suggest disabling
CONFIG_IP_NF_CT_ACCT [which can't be vital anyway, since it was only
added in net-2.6.14 (and thus -mm)].

Cheers,
-- 
- Harald Welte <laforge@netfilter.org>                 http://netfilter.org/
============================================================================
  "Fragmentation is like classful addressing -- an interesting early
   architectural error that shows how much experimentation was going
   on while IP was being designed."                    -- Paul Vixie

[-- Attachment #2: Type: application/pgp-signature, Size: 189 bytes --]

Re: 2.6.13-rc5-mm1: BUG: rwlock recursion on CPU#0

[Zwane Mwaikambo]

On Mon, 15 Aug 2005, Harald Welte wrote:

> On Sun, Aug 14, 2005 at 08:15:53PM -0600, Zwane Mwaikambo wrote:
> 
> > Is the following patch correct? ip_conntrack_event_cache should never be 
> > called with ip_conntrack_lock held and ct_add_counters does not need to be 
> > called with ip_conntrack_lock held.
> 
> No, it's not correct.  ct_add_countes has to be called from within
> write_lock_bh() on ip_conntrack_lock.
> 
> So if you keep the ct_add_counters() call where it is and only apply the
> rest of your patch (i.e. deferring of ip_conntrack_event_cache() call),
> then I think your patch would work.
> 
> However, the whole eventcache needs to be audited, it's called from a
> number of places.
> 
> As Patrick wrote he's working on a solution, I'm not going to intervene
> or replicate his work.  As a interim solution I'd suggest disabling
> CONFIG_IP_NF_CT_ACCT [which can't be vital anyway, since it was only
> added in net-2.6.14 (and thus -mm)].

Thanks for the explanation Harald, i based the ct_add_counters assumption 
on other callers of it.

Thanks,
	Zwane