two warns on slowpath

Hi,

Since loading netconsole a couple of days ago on the two machines of a heartbeat cluster hosting Xen virtual machines, I got the attached warn_on_slowpath messages, one on each. It never happened before, so I thought I could as well report them in case it's interesting for you. The netconsole module parameter is like

[email protected]/eth-gb1,[email protected]/00:09:6b:8c:88:6b

with different port numbers on the two hosts. The eth-gb[12] physical interfaces are bonded, but I couldn't run netconsole on bond0, as it has no netpoll support. The source IP is on bond0. There are also several 802.1q subinterfaces over bond0, which are bridge ports.

The kernel is basically 2.6.26.6 with the SuSE Xen patch for dom0 support (the Debian Lenny kernel).
---8<---

Firewall heartbeat: IN=lo OUT= MAC=00:00:00:00:00:00:00:00:<4>------------[ cut here ]------------

WARNING: at kernel/softirq.c:141 local_bh_enable+0x2e/0x78()
Modules linked in: pl2303 usbserial xt_physdev netconsole configfs video output ac battery bridge 8021q bonding ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 ipt_recent ipt_REJECT nf_conntrack_ipv4 xt_state nf_conntrack xt_tcpudp ipt_LOG xt_limit xt_multiport iptable_filter ip_tables x_tables ext2 mbcache loop dm_round_robin dm_emc dm_multipath evdev psmouse serio_raw shpchp pci_hotplug pcspkr button i2c_piix4 i2c_core sworks_agp agpgart dcdbas xfs dm_mirror dm_log dm_snapshot dm_mod raid1 md_mod sg ide_cd_mod cdrom sd_mod ata_generic libata dock aic7xxx scsi_transport_spi ohci_hcd tg3 serverworks floppy usbcore qla2xxx firmware_class scsi_transport_fc scsi_tgt ide_pci_generic ide_core scsi_mod thermal processor fan thermal_sys
Pid: 22191, comm: heartbeat Not tainted 2.6.26-1-xen-686 #1
 [<c011e631>] warn_on_slowpath+0x40/0x64
 [<c01e5b44>] _swiotlb_map_single+0xab/0x18b
 [<d1127932>] tg3_start_xmit_dma_bug+0x3a7/0x7d3 [tg3]
 [<d1127c97>] tg3_start_xmit_dma_bug+0x70c/0x7d3 [tg3]
 [<c0169551>] dma_pool_alloc+0x191/0x19b
 [<d10d861f>] ohci_urb_enqueue+0x4eb/0x6c2 [ohci_hcd]
 [<c0122eda>] local_bh_enable+0x2e/0x78
 [<d19e7753>] __nf_conntrack_find+0xd5/0xdc [nf_conntrack]
 [<d19e7761>] nf_conntrack_find_get+0x7/0x3d [nf_conntrack]
 [<d19e821c>] nf_conntrack_in+0x14c/0x404 [nf_conntrack]
 [<c01162a7>] enqueue_task_fair+0x16/0x24
 [<c0114f8e>] enqueue_task+0x52/0x5d
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<d1a946fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<d1a946fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<d1a952d6>] br_nf_pre_routing+0x51c/0x542 [bridge]
 [<d1a946fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<d1a91436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<d1a91436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<d1a9169f>] br_handle_frame+0x165/0x186 [bridge]
 [<d1a91436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<c0269ae9>] netif_receive_skb+0x2a5/0x391
 [<d112bf23>] tg3_poll+0x696/0x9bc [tg3]
 [<c01e55fc>] swiotlb_unmap_single+0x0/0x13
 [<c0274a2b>] netpoll_poll+0x74/0x348
 [<c0274df7>] netpoll_send_skb+0xf8/0x1b6
 [<d1a120b2>] write_msg+0x6d/0xa9 [netconsole]
 [<d1a12045>] write_msg+0x0/0xa9 [netconsole]
 [<c011e6aa>] __call_console_drivers+0x4f/0x5b
 [<c011eabb>] release_console_sem+0x15e/0x1e5
 [<c011ef89>] vprintk+0x2bb/0x317
 [<c011efaf>] vprintk+0x2e1/0x317
 [<c01dce4e>] __next_cpu+0x12/0x21
 [<c011eff9>] printk+0x14/0x18
 [<d180f8a6>] ipt_log_packet+0xf1/0x135 [ipt_LOG]
 [<d180f921>] log_tg+0x37/0x42 [ipt_LOG]
 [<d19b4001>] user2credits+0x1/0x2e [xt_limit]
 [<d19b0004>] ipt_local_out_hook+0x4/0x5c [iptable_filter]
 [<d180f8ea>] log_tg+0x0/0x42 [ipt_LOG]
 [<d19b7439>] ipt_do_table+0x38f/0x422 [ip_tables]
 [<c0126789>] lock_timer_base+0x19/0x35
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<c0284a93>] ip_local_deliver_finish+0x0/0x183
 [<c0284f3b>] ip_local_deliver+0x4d/0x66
 [<c0284a93>] ip_local_deliver_finish+0x0/0x183
 [<c0284a76>] ip_rcv_finish+0x286/0x2a3
 [<c0269b68>] netif_receive_skb+0x324/0x391
 [<c026c030>] process_backlog+0xe4/0x10a
 [<c026b9cd>] net_rx_action+0xb9/0x1cf
 [<c0122bf8>] __do_softirq+0x79/0xf4
 [<c0122cc4>] do_softirq+0x51/0x76
 [<c0122f19>] local_bh_enable+0x6d/0x78
 [<c026c72c>] dev_queue_xmit+0x3a2/0x3da
 [<c0287fb5>] ip_finish_output+0x1c5/0x1fc
 [<c0287b43>] ip_local_out+0x15/0x17
 [<c0287d96>] ip_push_pending_frames+0x251/0x2ab
 [<c029f210>] udp_push_pending_frames+0x2b0/0x315
 [<c02a021f>] udp_sendmsg+0x436/0x519
 [<c02a5071>] inet_sendmsg+0x35/0x3f
 [<c02609aa>] sock_sendmsg+0xc7/0xe1
 [<c012ec48>] autoremove_wake_function+0x0/0x2d
 [<c0263e8e>] sock_wfree+0x1f/0x35
 [<c01e55fc>] swiotlb_unmap_single+0x0/0x13
 [<c0261285>] sys_sendto+0xfc/0x127
 [<c0122cc4>] do_softirq+0x51/0x76
 [<c01e55fc>] swiotlb_unmap_single+0x0/0x13
 [<c01dfccc>] rb_insert_color+0x4c/0xad
 [<c01310aa>] enqueue_hrtimer+0x5a/0x62
 [<c0131548>] hrtimer_start+0x111/0x11d
 [<c0261b70>] sys_socketcall+0x106/0x19e
 [<c0103f76>] syscall_call+0x7/0xb
 =======================
---[ end trace 6aa9bbc52691d91c ]---

---8<---

Firewall heartbeat: IN=lo OUT= MAC=00:00:00:00:00:00:00:00:00:00:00:00:08:00 SRC=10.253.2.8 DST=10.253.2.8 LEN=238 TOS=0x10 PREC=0x00 TTL=64 ID=0 DF <4>------------[ cut here ]------------

WARNING: at kernel/softirq.c:141 local_bh_enable+0x2e/0x78()
Modules linked in: xt_physdev netconsole configfs video output ac battery bridge 8021q bonding ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 ipt_recent ipt_REJECT nf_conntrack_ipv4 xt_state nf_conntrack xt_tcpudp ipt_LOG xt_limit xt_multiport iptable_filter ip_tables x_tables ext2 mbcache dm_round_robin dm_emc dm_multipath loop evdev psmouse serio_raw shpchp pci_hotplug pcspkr button i2c_piix4 i2c_core sworks_agp agpgart dcdbas xfs dm_mirror dm_log dm_snapshot dm_mod raid1 md_mod sg ide_cd_mod cdrom sd_mod ata_generic libata dock aic7xxx scsi_transport_spi floppy qla2xxx firmware_class scsi_transport_fc scsi_tgt scsi_mod ohci_hcd tg3 serverworks ide_pci_generic ide_core usbcore thermal processor fan thermal_sys
Pid: 4871, comm: heartbeat Not tainted 2.6.26-1-xen-686 #1
 [<c011e631>] warn_on_slowpath+0x40/0x64
 [<d10c9932>] tg3_start_xmit_dma_bug+0x3a7/0x7d3 [tg3]
 [<d10c9c97>] tg3_start_xmit_dma_bug+0x70c/0x7d3 [tg3]
 [<d154986e>] __nf_ct_refresh_acct+0xd7/0x112 [nf_conntrack]
 [<d154cd15>] tcp_packet+0x911/0x97c [nf_conntrack]
 [<c01e5b44>] _swiotlb_map_single+0xab/0x18b
 [<c0122eda>] local_bh_enable+0x2e/0x78
 [<d1549753>] __nf_conntrack_find+0xd5/0xdc [nf_conntrack]
 [<d1549761>] nf_conntrack_find_get+0x7/0x3d [nf_conntrack]
 [<d154a21c>] nf_conntrack_in+0x14c/0x404 [nf_conntrack]
 [<d159067f>] bond_xmit_activebackup+0x43/0x5b [bonding]
 [<c026a287>] dev_hard_start_xmit+0x1eb/0x24f
 [<c026c72c>] dev_queue_xmit+0x3a2/0x3da
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<d15f66fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<d15f66fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<d15f72d6>] br_nf_pre_routing+0x51c/0x542 [bridge]
 [<d15f66fc>] br_nf_pre_routing_finish+0x0/0x239 [bridge]
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<d15f3436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<d15f3436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<d15f369f>] br_handle_frame+0x165/0x186 [bridge]
 [<d15f3436>] br_handle_frame_finish+0x0/0x104 [bridge]
 [<c0269ae9>] netif_receive_skb+0x2a5/0x391
 [<d10cdf23>] tg3_poll+0x696/0x9bc [tg3]
 [<c01e55fc>] swiotlb_unmap_single+0x0/0x13
 [<c0274a2b>] netpoll_poll+0x74/0x348
 [<c0274df7>] netpoll_send_skb+0xf8/0x1b6
 [<d15740b2>] write_msg+0x6d/0xa9 [netconsole]
 [<d1574045>] write_msg+0x0/0xa9 [netconsole]
 [<c011e6aa>] __call_console_drivers+0x4f/0x5b
 [<c011eabb>] release_console_sem+0x15e/0x1e5
 [<c011ef89>] vprintk+0x2bb/0x317
 [<c0131f11>] atomic_notifier_call_chain+0x9/0xc
 [<c022cbdb>] notify_update+0x1f/0x22
 [<c011eff9>] printk+0x14/0x18
 [<c011eff9>] printk+0x14/0x18
 [<d1371115>] dump_packet+0x100/0x7a0 [ipt_LOG]
 [<c011ef89>] vprintk+0x2bb/0x317
 [<c01061e9>] sched_clock+0x15/0x47
 [<c011eff9>] printk+0x14/0x18
 [<d13718d0>] ipt_log_packet+0x11b/0x135 [ipt_LOG]
 [<d1371921>] log_tg+0x37/0x42 [ipt_LOG]
 [<d1516001>] user2credits+0x1/0x2e [xt_limit]
 [<d13718ea>] log_tg+0x0/0x42 [ipt_LOG]
 [<d1519439>] ipt_do_table+0x38f/0x422 [ip_tables]
 [<c0126789>] lock_timer_base+0x19/0x35
 [<c027fb6c>] nf_iterate+0x30/0x61
 [<c027fbfb>] nf_hook_slow+0x3a/0x90
 [<c0284a93>] ip_local_deliver_finish+0x0/0x183
 [<c0284f3b>] ip_local_deliver+0x4d/0x66
 [<c0284a93>] ip_local_deliver_finish+0x0/0x183
 [<c0284a76>] ip_rcv_finish+0x286/0x2a3
 [<c0269b68>] netif_receive_skb+0x324/0x391
 [<c026c030>] process_backlog+0xe4/0x10a
 [<c026b9cd>] net_rx_action+0xb9/0x1cf
 [<c0122bf8>] __do_softirq+0x79/0xf4
 [<c0122cc4>] do_softirq+0x51/0x76
 [<c0122f19>] local_bh_enable+0x6d/0x78
 [<c026c72c>] dev_queue_xmit+0x3a2/0x3da
 [<c0287fb5>] ip_finish_output+0x1c5/0x1fc
 [<c0287b43>] ip_local_out+0x15/0x17
 [<c0287d96>] ip_push_pending_frames+0x251/0x2ab
 [<c029f210>] udp_push_pending_frames+0x2b0/0x315
 [<c02a021f>] udp_sendmsg+0x436/0x519
 [<c02a5071>] inet_sendmsg+0x35/0x3f
 [<c02609aa>] sock_sendmsg+0xc7/0xe1
 [<c012ec48>] autoremove_wake_function+0x0/0x2d
 [<c0263cc1>] sock_def_write_space+0xf/0x6c
 [<c0234388>] transmit_chars+0x5f/0xc5
 [<c0105f7c>] get_nsec_offset+0xe/0x6a
 [<c0261285>] sys_sendto+0xfc/0x127
 [<c01dfccc>] rb_insert_color+0x4c/0xad
 [<c01310aa>] enqueue_hrtimer+0x5a/0x62
 [<c0131548>] hrtimer_start+0x111/0x11d
 [<c0261b70>] sys_socketcall+0x106/0x19e
 [<c0103f76>] syscall_call+0x7/0xb
 =======================
---[ end trace 63fab894a4128708 ]---

---8<---

Regards,
Feri.

This report: http://marc.info/?l=linux-netdev&m=122599341430090&w=2
shows local_bh_enable() is used in the wrong context (irqs disabled). It happens when a usual network receive path is called by netconsole, which simply turns off irqs around this all. Probably this is wrong, but it worked like this long time, and it's not trivial to fix this.

Anyway, a commit 0f476b6d91a1395bda6464e653ce66ea9bea7167 "softirq:
remove irqs_disabled warning from local_bh_enable" can break things after changing from local_irq_save() to local_irq_disable(). Before this commit there was only a warning, now a lockup is possible, so it could be treated as a regression. This patch reverts the change in irqs.

---

 kernel/softirq.c |    7 +++++--
 1 files changed, 5 insertions(+), 2 deletions(-)

index e7c69a7..756c928 100644
@@ -135,9 +135,12 @@ EXPORT_SYMBOL(_local_bh_enable);
 
 static inline void _local_bh_enable_ip(unsigned long ip)
 {
+#ifdef CONFIG_TRACE_IRQFLAGS
+	unsigned long flags;
+#endif
 	WARN_ON_ONCE(in_irq() || irqs_disabled());
 #ifdef CONFIG_TRACE_IRQFLAGS
-	local_irq_disable();
+	local_irq_save(flags);
 #endif
 	/*
 	 * Are softirqs going to be turned on now:

@@ -155,7 +158,7 @@ static inline void _local_bh_enable_ip(unsigned long ip)
 
 	dec_preempt_count();
 #ifdef CONFIG_TRACE_IRQFLAGS
-	local_irq_enable();
+	local_irq_restore(flags);
 #endif
 	preempt_check_resched();
 }

Unfortunately my brain lacks the magic to decrypt x86 stack traces, so I'm unable to read much from that report other than that it hit the WARN_ON. That looks more like the TX path to me? Anyway, my patch made that trigger for everybody rather than just on NOPREEMPT/UP (or something like that) and made the code easier to understand by removing the flags that are pointless anyway if the API is used correctly.

You can find discussion around the patch at
http://lkml.org/lkml/2008/6/17/259

Do we have evidence of this actually hitting often? This is the first report of anything going wrong that I've seen ever since a single one right after this commit went into testing five months ago.

IFF we want to add this back (and I'm not in favour) then please add a big comment that this is only to accomodate broken users.

johannes

OK, this looks like both paths (which is probably common in networking).

Yes, it's very interesting.

Yes, it seems there should be more such reports from netconsole users. But, I guess we kind of expect this if we still use WARN_ON and not BUG_ON here?

Jarek P.

hm, but calling local_bh_enable() with hardirqs off is a bug. It might be a long-standing bug, but it can cause lockups even with that change
reverted: when we process softirqs in local_bh_enable(). So why not fix the bug instead?

Ingo

I think it's what they call a regression: this is a long-standing bug, and this commit doesn't fix this, but can cause additional lockups.

It's not about instead: this bug could be fixed as well (if somebody knows how to do it "properly" without hacks like:

	if (!in_irq())
		local_bh_disable();

etc.; but, I guess, the network code has more such bh disabling).

Jarek P.

This report: http://marc.info/?l=linux-netdev&m=122599341430090&w=2
shows local_bh_enable() is used in the wrong context (irqs disabled). It happens when a usual network path is called by netconsole, which simply turns off hardirqs around this all.

This patch additionally disables softirqs to avoid possibility of enabling bh and calling do_softirq() with hardirqs disabled.

---

 drivers/net/netconsole.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)

index d304d38..f6ecad8 100644
@@ -702,6 +702,8 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 	if (list_empty(&target_list))
 		return;
 
+	/* Avoid enabling softirqs with hardirqs disabled */
+	local_bh_disable();
 	spin_lock_irqsave(&target_list_lock, flags);
 	list_for_each_entry(nt, &target_list, list) {
 		netconsole_target_get(nt);

@@ -723,6 +725,7 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 		netconsole_target_put(nt);
 	}
 	spin_unlock_irqrestore(&target_list_lock, flags);
+	local_bh_enable();
 }
 
 static struct console netconsole = {

From: Ingo Molnar <[email protected]>
Date: Wed, 19 Nov 2008 10:30:04 +0100

Well, it sort of "has to". It calls the NAPI ->poll() method of the driver to try and make forward progress with TX reclaim so it can send new messages.

It is very careful not to recursively invoke into ->poll() and other nasty situations.

Didn't you write some of this code Ingo a very long time ago? :-)))

Anyways, I'll look more closely at this and the original report, this never was a problem before.

it is causing problems, so i'd like to distance myself from that careless mistake of my youth! [ And once it starts working again i'd like to take credit for having started that brilliant piece of innovation. ]

Thanks! We strengthened/cleaned up the bh checks a tiny bit recently, maybe that caused this to pop up. It might explain some netconsole lockups perhaps? Or, the new warning might be bogus. It's a bit of a maze.

Ingo

From: Ingo Molnar <[email protected]>
Date: Wed, 19 Nov 2008 11:14:41 +0100

See my other reply to Jarek's patch posting, we're supposed to ignore all RX packets in this situation, and all the logic appears to be there, but it's not happening on that person's system for some reason.

Saw that ... an insanely complex scenario.

So at least there's a partial result: it appears to not be a false positive warning in the generic softirq/lockdep code.

Ingo

From: Ingo Molnar <[email protected]>
Date: Wed, 19 Nov 2008 11:21:46 +0100

Right, it's totally legit.

From: Jarek Poplawski <[email protected]>
Date: Wed, 19 Nov 2008 08:41:06 +0000

This backtrace call path is anything but "usual".

There is a UDP send, and a local_bh_enable() done there triggers softirqs, which processes device (I would guess loopback, or some non-NAPI device) backlog processing.

This triggers an input netfilter ipt_LOG rule, which triggers a printk over netconsole.

netpoll finds the TX queue of the tg3 device (which is NAPI) full, so it invokes ->poll() to try and free up some TX queue space.

This in turn triggers a packet receive, which hits bridging netfilter, which does a conntrack lookup, which does the BH disable/enable which triggers the warning.

I mean, this is just a very crazy trace :-)

I see an easy way around this. We should just punt on non-netpoll RX packets that try to get processed during a netconsole ->poll() run.

Wait a second, this is _supposed_ to be already happening. Perhaps the tests in netpoll_rx() are screwed up.

net/core/netpoll.c'd poll_one_napi() explicitly sets NETPOLL_RX_DROP in npinfo->rx_flags as well as increment "trapped", and that is supposed to make netpoll_rx() return non-zero which tells the caller to ignore and drop all RX packets.

What isn't that happening?

netpoll_rx()'s test is:

	if (!npinfo || (!npinfo->rx_np && !npinfo->rx_flags))
		return 0;

which looks perfectly fine. npinfo will be non-NULL by definition because we are doing netpoll for netconsole on this device, and ->rx_flags are non-zero by the above mentioned code.

So we get to __netpoll_rx() by the next bit of code.

	if (npinfo->rx_flags && __netpoll_rx(skb))
		ret = 1;

And __netpoll_rx() says:

	struct netpoll *np = npi->rx_np;

	if (!np)
		goto out;

this should trigger because a netpoll RX agent shouldn't be attached, then:

out:

	if (atomic_read(&trapped)) {
		kfree_skb(skb);
		return 1;
	}

	return 0;

which should trigger because trapped is non-zero, thus we free the SKB and return 1.

We need to figure out why this isn't working properly. Maybe it's some bug we fixed, or some weird change in the SUSE Xen mods this used has applied.

I also took a quick look at 2.6.26.6 and I don't see any bugs in this area there.

Consider netconsole case as special in local_bh_enable()/_disable(). This patch skips in_irq() and irqs_disabled() warnings for NETPOLL configs when it's safe wrt. do_softirq().

---
[apply on top of my first softirq patch in this thread]

diff -Nurp a/kernel/softirq.c b/kernel/softirq.c
@@ -76,7 +76,12 @@ static void __local_bh_disable(unsigned 
 {
 	unsigned long flags;
 
+#ifdef CONFIG_NETPOLL
+	if (!softirq_count())
+		WARN_ON_ONCE(in_irq());
+#else
 	WARN_ON_ONCE(in_irq());
+#endif
 
 	raw_local_irq_save(flags);
 	add_preempt_count(SOFTIRQ_OFFSET);

@@ -138,7 +143,16 @@ static inline void _local_bh_enable_ip(u
 #ifdef CONFIG_TRACE_IRQFLAGS
 	unsigned long flags;
 #endif
+#ifdef CONFIG_NETPOLL
+	/*
+	 * Special-case - netconsole runs network code with all interrupts
+	 * disabled. Warn only if it can be really dangerous:
+	 */
+	if (softirq_count() == SOFTIRQ_OFFSET)
+		WARN_ON_ONCE(in_irq() || irqs_disabled());
+#else
 	WARN_ON_ONCE(in_irq() || irqs_disabled());
+#endif
 #ifdef CONFIG_TRACE_IRQFLAGS
 	local_irq_save(flags);
 #endif

Well, it's a question of taste. Anyway, this patch is only about warnings, so no big deal. But I still think the first patch reverting local_irq_save() -> local_irq_disable() change should be applied. There is no need to give users any additional lockups risk while we know there are unsolved issues.

BTW, the current situation with: local_irq_disable() in _local_bh_enable() and local_irq_save() in do_softirq() doesn't make much sense. I know, there is local_irq_disable() in __do_softirq() again, but it can be often skipped on this path because of in_interrupt() test (and there is soon this local_irq_restore() in do_softirq()).

Jarek P.