two warns on slowpath

two warns on slowpath

[Ferenc Wagner]

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

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

netconsole=@10.253.2.8/eth-gb1,6666@10.253.2.1/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<---

[-- Attachment #2: slow1b.txt --]
[-- Type: text/plain, Size: 4333 bytes --]

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 ]---

[-- Attachment #3: Type: text/plain, Size: 9 bytes --]

---8<---

[-- Attachment #4: slow2b.txt --]
[-- Type: text/plain, Size: 4592 bytes --]

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 ]---

[-- Attachment #5: Type: text/plain, Size: 28 bytes --]

---8<---
-- 
Regards,
Feri.

[PATCH] softirq: Use local_irq_save() in local_bh_enable()

[Jarek Poplawski]

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.

Reported-by: Ferenc Wagner <wferi@niif.hu>
Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
---

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

diff --git a/kernel/softirq.c b/kernel/softirq.c
index e7c69a7..756c928 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -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();
 }

Re: [PATCH] softirq: Use local_irq_save() in local_bh_enable()

[Johannes Berg]

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

On Mon, 2008-11-17 at 13:35 +0000, Jarek Poplawski wrote:
> 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.

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

> 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.

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

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [PATCH] softirq: Use local_irq_save() in local_bh_enable()

[Jarek Poplawski]

On Mon, Nov 17, 2008 at 03:18:28PM +0100, Johannes Berg wrote:
> On Mon, 2008-11-17 at 13:35 +0000, Jarek Poplawski wrote:
> > 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.
> 
> 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?

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

> 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

Yes, it's very interesting.

> 
> > 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.
> 
> 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.

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.

Re: [PATCH] softirq: Use local_irq_save() in local_bh_enable()

[Ingo Molnar]

* Jarek Poplawski <jarkao2@gmail.com> wrote:

> 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.

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

Re: [PATCH] softirq: Use local_irq_save() in local_bh_enable()

[Jarek Poplawski]

On Mon, Nov 17, 2008 at 05:16:17PM +0100, Ingo Molnar wrote:
> 
> * Jarek Poplawski <jarkao2@gmail.com> wrote:
> 
> > 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.
> 
> 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().

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.

> So why not 
> fix the bug instead?

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.

[PATCH] netconsole: Disable softirqs in write_msg()

[Jarek Poplawski]

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.

Reported-by: Ferenc Wagner <wferi@niif.hu>
Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
---

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

diff --git a/drivers/net/netconsole.c b/drivers/net/netconsole.c
index d304d38..f6ecad8 100644
--- a/drivers/net/netconsole.c
+++ b/drivers/net/netconsole.c
@@ -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 = {

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[Ingo Molnar]

* Jarek Poplawski <jarkao2@gmail.com> wrote:

> 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.
> 
> Reported-by: Ferenc Wagner <wferi@niif.hu>
> Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
> ---
> 
>  drivers/net/netconsole.c |    3 +++
>  1 files changed, 3 insertions(+), 0 deletions(-)
> 
> diff --git a/drivers/net/netconsole.c b/drivers/net/netconsole.c
> index d304d38..f6ecad8 100644
> --- a/drivers/net/netconsole.c
> +++ b/drivers/net/netconsole.c
> @@ -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();

but netconsole can be triggered from printk - and printk can be called 
from hardirqs-off sections - so this doesnt really fix the bug. 
Netconsole should not do BH processing.

	Ingo

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[David Miller]

From: Ingo Molnar <mingo@elte.hu>
Date: Wed, 19 Nov 2008 10:30:04 +0100

> * Jarek Poplawski <jarkao2@gmail.com> wrote:
> 
> > diff --git a/drivers/net/netconsole.c b/drivers/net/netconsole.c
> > index d304d38..f6ecad8 100644
> > --- a/drivers/net/netconsole.c
> > +++ b/drivers/net/netconsole.c
> > @@ -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();
> 
> but netconsole can be triggered from printk - and printk can be called 
> from hardirqs-off sections - so this doesnt really fix the bug. 
> Netconsole should not do BH processing.

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.

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[Ingo Molnar]

* David Miller <davem@davemloft.net> wrote:

> From: Ingo Molnar <mingo@elte.hu>
> Date: Wed, 19 Nov 2008 10:30:04 +0100
> 
> > * Jarek Poplawski <jarkao2@gmail.com> wrote:
> > 
> > > diff --git a/drivers/net/netconsole.c b/drivers/net/netconsole.c
> > > index d304d38..f6ecad8 100644
> > > --- a/drivers/net/netconsole.c
> > > +++ b/drivers/net/netconsole.c
> > > @@ -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();
> > 
> > but netconsole can be triggered from printk - and printk can be called 
> > from hardirqs-off sections - so this doesnt really fix the bug. 
> > Netconsole should not do BH processing.
> 
> 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? :-)))

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. ]

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

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

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[David Miller]

From: Ingo Molnar <mingo@elte.hu>
Date: Wed, 19 Nov 2008 11:14:41 +0100

> 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.

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.

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[Ingo Molnar]

* David Miller <davem@davemloft.net> wrote:

> From: Ingo Molnar <mingo@elte.hu>
> Date: Wed, 19 Nov 2008 11:14:41 +0100
> 
> > 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.
> 
> 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

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[David Miller]

From: Ingo Molnar <mingo@elte.hu>
Date: Wed, 19 Nov 2008 11:21:46 +0100

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

Right, it's totally legit.

Re: [PATCH] netconsole: Disable softirqs in write_msg()

[David Miller]

From: Jarek Poplawski <jarkao2@gmail.com>
Date: Wed, 19 Nov 2008 08:41:06 +0000

> 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 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.

[PATCH] softirq: Fix warnings triggered by netconsole

[Jarek Poplawski]

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().

Reported-by: Ferenc Wagner <wferi@niif.hu>
Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
---
[apply on top of my first softirq patch in this thread]

diff -Nurp a/kernel/softirq.c b/kernel/softirq.c
--- a/kernel/softirq.c	2008-11-19 07:33:23.000000000 +0000
+++ b/kernel/softirq.c	2008-11-19 07:26:28.000000000 +0000
@@ -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

Re: [PATCH] softirq: Fix warnings triggered by netconsole

[Ingo Molnar]

* Jarek Poplawski <jarkao2@gmail.com> wrote:

> 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().
> 
> Reported-by: Ferenc Wagner <wferi@niif.hu>
> Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
> ---
> [apply on top of my first softirq patch in this thread]
> 
> diff -Nurp a/kernel/softirq.c b/kernel/softirq.c
> --- a/kernel/softirq.c	2008-11-19 07:33:23.000000000 +0000
> +++ b/kernel/softirq.c	2008-11-19 07:26:28.000000000 +0000
> @@ -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

this is a very ugly patch, not really acceptable.

printk methods should not be doing softirq processing - period.

	Ingo

Re: [PATCH] softirq: Fix warnings triggered by netconsole

[Jarek Poplawski]

On Wed, Nov 19, 2008 at 10:32:24AM +0100, Ingo Molnar wrote:
> 
> * Jarek Poplawski <jarkao2@gmail.com> wrote:
> 
> > 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().
> > 
> > Reported-by: Ferenc Wagner <wferi@niif.hu>
> > Signed-off-by: Jarek Poplawski <jarkao2@gmail.com>
> > ---
> > [apply on top of my first softirq patch in this thread]
> > 
> > diff -Nurp a/kernel/softirq.c b/kernel/softirq.c
> > --- a/kernel/softirq.c	2008-11-19 07:33:23.000000000 +0000
> > +++ b/kernel/softirq.c	2008-11-19 07:26:28.000000000 +0000
> > @@ -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
> 
> this is a very ugly patch, not really acceptable.

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.