2009-06-02 13:06:57

by Andreas Mohr

[permalink] [raw]
Subject: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

Hello Karsten,

I'm having a hell of a time trying to get the
Linux 2.6.29.4
mISDN git (socket), and also kernel previously
mISDNuser git (socket)
lcr git (and also 20090107 previously)
Asterisk 1:1.4.21.2~dfsg-3
combo to work even marginally here.
Worse, the migration attempt (from i4l) even forced me to disable
regularly-used functionality (isdnlog) due to missing CAPI functionality
of mISDN or alternatively mISDN capability of isdnlog.

I had managed a *working* outgoing call setup Asterisk -> LCR -> ISDN *once*
(by re-loading modules after boot, however boot state itself
didn't work directly), but never since.

I have the suspicion that maybe I shouldn't be loading hisax upon boot
(and then immediately removing it before launching mISDN stuff),
since hfcpci acts very weird - perhaps it cannot recover card state fully
after hisax fumbling.

I will have to test this more.

This is on a Lenny K6-III/150 box (yes, in ACPI mode!!!), 128M, 8G CF.

Might need to revert to non-ACPI operation after all *SIGH*


Behaviour was something like:

base_sock_release(c7600000) sk=c6f84a00
base_sock_release(c7600200) sk=c6f84400
base_sock_release(c7600400) sk=c7ab5800
init_card: entered
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(14) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 1
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(4) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 2
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(14) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 3
create_l2entity: ret 1 -5
base_sock_release(c7600400) sk=c6f94e00
init_card: entered
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(14) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 1
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(4) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 2
reset_hfcpci: entered
HFC_PCI: resetting HFC ChipId(30)
HFC-PCI status(14) before reset
HFC-PCI status(2) after reset
HFC-PCI status(4) after 5us
inithfcpci: entered
HFC PCI: IRQ 12 count 0
HFC PCI: IRQ(12) getting no interrupts during init 3
create_l2entity: ret 1 -5
HiSax: release hfcpci at c8826000
HiSax module removed
ISDN-subsystem unloaded
DSP modul 2.0
mISDN_dsp: DSP clocks every 80 samples. This equals 1 jiffies.



which resulted in cat /proc/interrupts showing multiple "HFC PCI" entries
after a couple of failed request_irq() iterations.
rmmod'ing hfcpci and then doing cat /proc/interrupts quickly led to
a network-killing OOPS.

Note that I still get a WARN_ON even with my hopefully(?) improved version:


------------[ cut here ]------------
WARNING: at kernel/softirq.c:124 _local_bh_enable_ip+0x31/0x6f()
Hardware name:
Modules linked in: hfcpci tun cls_u32 sch_sfq sch_tbf sch_prio sch_ingress sch_htb sch_cbq capifs xt_state xt_multiport xt_tcpudp xt_recent xt_limit iptable_mangle iptable_nat iptable_filter ip_tables nf_nat_tftp nf_conntrack_tftp nf_nat_h323 nf_conntrack_h323 nf_nat_irc nf_nat_ftp nf_conntrack_irc nf_conntrack_ftp ipt_MASQUERADE nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack ipt_REJECT ipt_LOG x_tables fuse 8021qgarp stp llc usb_storage ehci_hcd ohci_hcd sis5595 i2c_sis5595 i2c_sis630 e100 usbcore i2c_core mISDN_core [last unloaded: mISDN_dsp]
Pid: 3462, comm: mISDN_hfc-pci.1 Not tainted 2.6.29.4-gate #1
Call Trace:
[<c0118049>] warn_slowpath+0x71/0xa7
[<c013c2bd>] ? __rmqueue+0x16/0x1b0
[<c03526ff>] ? _spin_unlock+0x8/0xa
[<c013d353>] ? rmqueue_bulk+0x5e/0x68
[<c013d500>] ? get_page_from_freelist+0x1a3/0x32e
[<c013d726>] ? __alloc_pages_internal+0x9b/0x358
[<c011bee3>] _local_bh_enable_ip+0x31/0x6f
[<c011bf36>] local_bh_enable+0xb/0xd
[<c02eb443>] sk_filter+0x5a/0x63
[<c02d9f1f>] sock_queue_rcv_skb+0x2b/0xc8
[<c893f5b3>] mISDN_send+0x4e/0x71 [mISDN_core]
[<c8941dff>] l2up_create+0x6f/0x96 [mISDN_core]
[<c8944547>] l2_got_tei+0x3b/0x77 [mISDN_core]
[<c893e74d>] mISDN_FsmEvent+0x74/0xa8 [mISDN_core]
[<c894450c>] ? l2_got_tei+0x0/0x77 [mISDN_core]
[<c8943740>] tei_l2+0x73/0xa3 [mISDN_core]
[<c8945636>] tei_id_assign+0xab/0xb3 [mISDN_core]
[<c893e74d>] mISDN_FsmEvent+0x74/0xa8 [mISDN_core]
[<c894558b>] ? tei_id_assign+0x0/0xb3 [mISDN_core]
[<c89465f2>] mgr_send+0x30b/0x4d1 [mISDN_core]
[<c0351ad6>] ? __mutex_lock_slowpath+0x12/0x15
[<c0351b5b>] ? mutex_lock+0x1c/0x1f
[<c8940f4d>] mISDNStackd+0x216/0x4f1 [mISDN_core]
[<c01271ab>] ? autoremove_wake_function+0x0/0x33
[<c8940d37>] ? mISDNStackd+0x0/0x4f1 [mISDN_core]
[<c0126f9a>] kthread+0x39/0x5e
[<c0126f61>] ? kthread+0x0/0x5e
[<c0103497>] kernel_thread_helper+0x7/0x10
---[ end trace 080cb55fd8ea9459 ]---

which hints at IRQ disable issues (maybe due to my change even??),
but I've got no friggin clue...




Also, misdn_log doesn't seem to do much here either:

# misdn_log
mISDN kernel version 1.01.20 found
mISDN user version 1.01.20 found
1 controller found
id: 0
Dprotocols: 00000006
Bprotocols: 0000000e
protocol: 1
channelmap: 00000000000000000000000000000006
nrbchan: 2
name: hfc-pci.1
log bind ch(1) return -1
log bind error Invalid argument
log bind ch(0) return -1
log bind error Operation already in progress

(strace hints at PF_ISDN socket issues)


Thanks!




ChangeLog:
Make sure to properly bail out (call free_irq())
after hfcpci interrupt detection failure.
Improve comment.

Signed-off-by: Andreas Mohr <[email protected]>

--- ./drivers/isdn/hardware/mISDN/hfcpci.c.orig 2009-06-02 13:54:10.000000000 +0200
+++ ./drivers/isdn/hardware/mISDN/hfcpci.c 2009-06-02 14:29:20.000000000 +0200
@@ -1172,7 +1172,7 @@ hfcpci_int(int intno, void *dev_id)
printk(KERN_DEBUG
"HFC-PCI: stat(%02x) s1(%02x)\n", stat, val);
} else {
- /* shared */
+ /* (shared) IRQ triggered by other device */
spin_unlock(&hc->lock);
return IRQ_NONE;
}
@@ -1807,8 +1807,7 @@ init_card(struct hfc_pci *hc)
"HFC PCI: IRQ(%d) getting no interrupts "
"during init %d\n", hc->irq, 4 - cnt);
if (cnt == 1) {
- spin_unlock_irqrestore(&hc->lock, flags);
- return -EIO;
+ goto fail;
} else {
reset_hfcpci(hc);
cnt--;
@@ -1819,6 +1818,7 @@ init_card(struct hfc_pci *hc)
return 0;
}
}
+fail:
disable_hwirq(hc);
spin_unlock_irqrestore(&hc->lock, flags);
free_irq(hc->irq, hc);


2009-06-02 14:02:56

by Andreas Mohr

[permalink] [raw]
Subject: Re: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

Hi,

> I have the suspicion that maybe I shouldn't be loading hisax upon boot
> (and then immediately removing it before launching mISDN stuff),
> since hfcpci acts very weird - perhaps it cannot recover card state fully
> after hisax fumbling.

Indeed, manually killed all hisax modules on the system, rebooted, and -
it worked, immediately!
(test call SIP -> Asterisk -> LCR -> ISDN -> out -> ISDN)

IOW, we've got an unfortunate driver init state handling issue which one
should perhaps investigate to make the driver more robust against
varying hardware state.
(my IRQ patch was a first step I guess ;)

misdn_log still acts weird, though...

Thanks for all your important ISDN work! (given the sizeable number of
commits mISDN will rather soon get there I think)

BTW, could isdnlog be adapted to support mISDN relatively easily?
(since adding CAPI support would take longer I guess)
My guys are going semi-ballistic with their isdnlog taken out and shot ;)

Andreas Mohr

2009-06-02 14:59:13

by Karsten Keil

[permalink] [raw]
Subject: Re: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

On Dienstag, 2. Juni 2009 16:02:50 you wrote:
> Hi,
>
> > I have the suspicion that maybe I shouldn't be loading hisax upon boot
> > (and then immediately removing it before launching mISDN stuff),
> > since hfcpci acts very weird - perhaps it cannot recover card state fully
> > after hisax fumbling.
>
> Indeed, manually killed all hisax modules on the system, rebooted, and -
> it worked, immediately!
> (test call SIP -> Asterisk -> LCR -> ISDN -> out -> ISDN)
>
> IOW, we've got an unfortunate driver init state handling issue which one
> should perhaps investigate to make the driver more robust against
> varying hardware state.
> (my IRQ patch was a first step I guess ;)
>

Yes from mISDN side, but I do not see what inside hisax prevent mISDN from
getting IRQs after hisax was unloaded. And it works here on my test setup, I
can load mISDN without an error, after unloading hisax.
One other issue with the HiSax HFC PCI code is the FIFO DMA memory
allocation, this code is wrong and broken (patch is under test).

> misdn_log still acts weird, though...
>
What does be weird here ?

> Thanks for all your important ISDN work! (given the sizeable number of
> commits mISDN will rather soon get there I think)
>
> BTW, could isdnlog be adapted to support mISDN relatively easily?
> (since adding CAPI support would take longer I guess)

isdnlog (beside that the isdnlog code is ugly enough) should be not a big
issue, mISDN supports logging in parallel to the normal work, look at the
tools/loghex.c code how to create a logging socket.
It should make things easier as with HiSax, since it will get the data as
binary and not as hexdump.

> My guys are going semi-ballistic with their isdnlog taken out and shot ;)
>
> Andreas Mohr
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/

2009-06-02 15:30:15

by Karsten Keil

[permalink] [raw]
Subject: Re: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

Hi Andreas,

On Dienstag, 2. Juni 2009 15:06:49 Andreas Mohr wrote:

Thanks for discovering this issue.

...
> ChangeLog:
> Make sure to properly bail out (call free_irq())
> after hfcpci interrupt detection failure.
> Improve comment.
>
> Signed-off-by: Andreas Mohr <[email protected]>
>
> --- ./drivers/isdn/hardware/mISDN/hfcpci.c.orig 2009-06-02
> 13:54:10.000000000 +0200 +++
> ./drivers/isdn/hardware/mISDN/hfcpci.c 2009-06-02 14:29:20.000000000 +0200
> @@ -1172,7 +1172,7 @@ hfcpci_int(int intno, void *dev_id)
> printk(KERN_DEBUG
> "HFC-PCI: stat(%02x) s1(%02x)\n", stat, val);
> } else {
> - /* shared */
> + /* (shared) IRQ triggered by other device */
> spin_unlock(&hc->lock);
> return IRQ_NONE;
> }

Hmm, I think shared as comment in the IRQ function should be
enough - but I do not complain to a longer comment.

> @@ -1807,8 +1807,7 @@ init_card(struct hfc_pci *hc)
> "HFC PCI: IRQ(%d) getting no interrupts "
> "during init %d\n", hc->irq, 4 - cnt);
> if (cnt == 1) {
> - spin_unlock_irqrestore(&hc->lock, flags);
> - return -EIO;
> + goto fail;
> } else {
> reset_hfcpci(hc);
> cnt--;

easier:
if (cnt == 1)
break;
else {


I will send this patch together with some other ISDN fixes again soon.

Karsten


2009-06-02 15:44:47

by Andreas Mohr

[permalink] [raw]
Subject: Re: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

Hi,

On Tue, Jun 02, 2009 at 04:53:35PM +0200, Karsten Keil wrote:
> Yes from mISDN side, but I do not see what inside hisax prevent mISDN from
> getting IRQs after hisax was unloaded. And it works here on my test setup, I
> can load mISDN without an error, after unloading hisax.

Mayyybe it's due to using kernel hisax with non-kernel (GIT) mISDN?

> > misdn_log still acts weird, though...
> >
> What does be weird here ?

See first mail.

> > BTW, could isdnlog be adapted to support mISDN relatively easily?
> > (since adding CAPI support would take longer I guess)
>
> isdnlog (beside that the isdnlog code is ugly enough) should be not a big
> issue, mISDN supports logging in parallel to the normal work, look at the
> tools/loghex.c code how to create a logging socket.
> It should make things easier as with HiSax, since it will get the data as
> binary and not as hexdump.

Of course one could get "something" out of a socket-based log sink,
but that "something" would likely be much less than the caller-resolving,
application-spawning stuff that isdnlog does - at least initially.


BTW, I'm migrating towards ISDN via KabelBW modem.

Andreas Mohr

2009-06-02 15:46:23

by Andreas Mohr

[permalink] [raw]
Subject: Re: [PATCH] mISDN GIT: hfcpci cleanup failure on IRQ weirdness

Hi,

On Tue, Jun 02, 2009 at 05:29:58PM +0200, Karsten Keil wrote:
> Hmm, I think shared as comment in the IRQ function should be
> enough - but I do not complain to a longer comment.

OK, whatever. It has better verbosity, but maybe too much.

> easier:
> if (cnt == 1)
> break;
> else {
>
>
> I will send this patch together with some other ISDN fixes again soon.

Thanks!

Andreas Mohr