NT-Modus L1Link Up aber keine Verbindung möglich

[bsel]

Hallo,

nach einigen Monaten - verbracht mit Testen und Suchen - komme ich zu dem Schluss, dass ich mal nachfragen sollte

Das Problem:
Alles läuft ein paar Stunden perfekt, und dann funktioniert das ISDN am Asterisk nicht mehr.


Ich habe folgende Konfiguration:
Software:
- Debian Sarge mit 2.6.8 selbstkompilieren mISDN-fähigem Linux
- Asterisk 1.2.13 built on a i686 running Linux on 2006-10-25 21:14:17 UTC
- chan_misdn-0.3.1-rc26
- mISDN 1.0.4 (ist um den 14. November aus 'm CVS gezogen)
Hardware:
- NTBA
- ISDN TA PCI-Karte [Cologne Chip Designs GmbH ISDN network controller [HFC-PCI] (rev 02)]
- Telefonanlage: Emmerich ISTEC 1008
- gekreuztes ISDN Kabel (Elektriker brüderlicherseits hat das Kabel neu verlötet; also nicht gecrimpt!)
- normales ISDN Kabel
- Analoge Reihenanlage

Es wurde mit Hilfe des install-misdn-mqueue-Skript installiert.

Hardware-Setup:
Analoge Reihenanlage <=> ISTEC 1008 <=> NTBA <=gekreuzt=> ISDN Karte = mISDN = Asterisk <=> Internet

Die ISTEC 1008 nimmt alles von der Reihenanlage analog entgegen und verfügt über einen ISDN Port, der an den NTBA angeschlossen wird. Die ISTEC versorgt auch den ISDN-Bus mit Strom.
Der NTBA ist nicht über seinen Netzanschluss mit dem Stromnetz verbunden (habe ich allerdings auch schon versucht).

Konfigurationsdateien:
/etc/misdn-init.conf:

card=1,hfcpci
nt_ptmp=1
poll=128
dsp_options=0
debug=0

/etc/asterisk/misdn.conf:

[general] 
misdn_init=/etc/misdn-init.conf
debug=4
ntdebugflags=0
ntdebugfile=/var/log/asterisk/misdn-nt.log
;tracefile=/var/log/asterisk/misdn.log

bridging=yes

stop_tone_after_first_digit=yes
append_digits2exten=yes

dynamic_crypt=no
;;crypt_prefix=**
;;crypt_keys=test,muh

[default]
context=misdn
language=de
musicclass=default
senddtmf=yes
far_alerting=no
allowed_bearers=all

nationalprefix=0
internationalprefix=00

rxgain=0
txgain=0
te_choose_channel=no
pmp_l1_check=yes
;pmp_l1_check=no
reject_cause=16
need_more_infos=no
nttimeout=no
method=standard
dialplan=0
localdialplan=0
cpndialplan=0
early_bconnect=yes
;early_bconnect=no
incoming_early_audio=no
;always_immediate=no
nodialtone=no
;immediate=no
;hold_allowed=yes
;callgroup=1
;pickupgroup=1
presentation=-1
screen=-1
;echocancel=no
jitterbuffer=4000
jitterbuffer_upper_threshold=0
hdlc=no

[NTPorts]
ports=1
context=outgoing
;l1watcher_timeout=0

Auszug aus /etc/asterisk/extenstion.conf:

exten => isdnforward,1,SetCallerID(${CALLERIDNUM})
exten => isdnforward,2,Dial(mISDN/1/1234,90)
exten => isdnforward,3,Congestion
exten => isdnforward,102,Busy

[outgoing]
exten => 23,1,Dial(SIP/069123456@sip_out,60,trg)
exten => 23,102,Hangup

exten => _0N.,1,Set(CALLERID(number)=123456)
exten => _0N.,2,Set(TIMEOUT(response)=20)
exten => _0N.,3,Wait(15)
exten => _0N.,4,Dial(SIP/${EXTEN}@sip_out,90,trg)
exten => _0N.,102,Hangup

Logdateien:
misdn.log (Kompletter Ausschnitt ohne Auslassung!):

[I][B]Zum Test den Hörer abheben und den Asterisk anwählen[/B][/I]
Wed Nov 22 00:18:35 2006: P[ 1]  % GOT L2 Activate Info.
Wed Nov 22 00:18:35 2006: P[ 1]  find_free_chan: req_chan:0
Wed Nov 22 00:18:35 2006: P[ 1]   --> found chan: 1
Wed Nov 22 00:18:35 2006: P[ 1]  set_channel: bc->channel:1 channel:255
Wed Nov 22 00:18:35 2006: P[ 1]   --> PTMP but channel requested
Wed Nov 22 00:18:35 2006: P[ 1]  I IND :SETUP oad: dad: pid:7 state:none
Wed Nov 22 00:18:35 2006: P[ 1]   --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 00:18:35 2006: P[ 1]   --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
Wed Nov 22 00:18:35 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 00:18:35 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 00:18:35 2006: P[ 1]   --> addr:0 l3id:10042 b_stid:0 layer_id:50010180
Wed Nov 22 00:18:35 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 00:18:35 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 00:18:35 2006: P[ 1]   --> Bearer: Speech
Wed Nov 22 00:18:35 2006: P[ 1]   --> Codec: Alaw
Wed Nov 22 00:18:36 2006: P[ 0]   --> * NEW CHANNEL dad: oad:
Wed Nov 22 00:18:36 2006: P[ 1]   --> CTON: Unknown
Wed Nov 22 00:18:36 2006: P[ 1]  EXPORT_PID: pid:7
Wed Nov 22 00:18:36 2006: P[ 1]   --> PRES: Restricted (0)
Wed Nov 22 00:18:36 2006: P[ 1]   --> SCREEN: Unscreened (0)
Wed Nov 22 00:18:36 2006: P[ 1]  * Queuing chan 0x8139708
Wed Nov 22 00:18:36 2006: P[ 1]  I SEND:SETUP_ACKNOWLEDGE oad: dad: pid:7
Wed Nov 22 00:18:36 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 00:18:36 2006: P[ 1]   --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 00:18:36 2006: P[ 1]   --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
Wed Nov 22 00:18:36 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 00:18:36 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 00:18:36 2006: P[ 1]   --> addr:0 l3id:10042 b_stid:0 layer_id:50010180
Wed Nov 22 00:18:36 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 00:18:36 2006: P[ 1]  setup_bc: with dsp
Wed Nov 22 00:18:36 2006: P[ 1]   --> Channel is 1
Wed Nov 22 00:18:36 2006: P[ 1]   --> TRANSPARENT Mode
Wed Nov 22 00:18:36 2006: P[ 1]   --> Dial
Wed Nov 22 00:18:36 2006: P[ 1]  misdn_write: zero write
Wed Nov 22 00:18:36 2006: P[ 1]  Starting Playtones
Wed Nov 22 00:18:36 2006: P[ 1]  BCHAN: bchan ACT Confirm pid:7
[I][B]Lege auf, da Freiton zu hören ist[/B][/I]
Wed Nov 22 00:18:39 2006: P[ 1]  I IND :DISCONNECT oad: dad: pid:7 state:WAITING4DIGS
Wed Nov 22 00:18:39 2006: P[ 1]   --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 00:18:39 2006: P[ 1]   --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> addr:50010102 l3id:10042 b_stid:10010100 layer_id:50010180
Wed Nov 22 00:18:39 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 00:18:39 2006: P[ 1]   --> bc_state:BCHAN_ACTIVATED
Wed Nov 22 00:18:39 2006: P[ 1]  $$$ find_holded: --> holded:0 channel:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> org:2 nt:1, inbandavail:0 state:1
Wed Nov 22 00:18:39 2006: P[ 1]  hangup_chan
Wed Nov 22 00:18:39 2006: P[ 1]  -> hangup
Wed Nov 22 00:18:39 2006: P[ 1]  * IND : HANGUP	pid:7 ctx:outgoing dad: oad:(null) State:WAITING4DIGS
Wed Nov 22 00:18:39 2006: P[ 1]   --> l3id:10042
Wed Nov 22 00:18:39 2006: P[ 1]   --> cause:16
Wed Nov 22 00:18:39 2006: P[ 1]   --> out_cause:16
Wed Nov 22 00:18:39 2006: P[ 1]   --> state:WAITING4DIGS
Wed Nov 22 00:18:39 2006: P[ 1]  I SEND:RELEASE oad: dad: pid:7
Wed Nov 22 00:18:39 2006: P[ 1]   --> bc_state:BCHAN_ACTIVATED
Wed Nov 22 00:18:39 2006: P[ 1]   --> channel:1 mode:NT cause:16 ocause:-1 rad: cad:
Wed Nov 22 00:18:39 2006: P[ 1]   --> info_dad: onumplan:  dnumplan:  rnumplan:  cpnnumplan:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> addr:50010102 l3id:10042 b_stid:10010100 layer_id:50010180
Wed Nov 22 00:18:39 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 00:18:39 2006: P[ 1]  Channel: mISDN/1-1 hanguped new state:CLEANING
Wed Nov 22 00:18:39 2006: P[ 1]  empty_chan_in_stack: 1
Wed Nov 22 00:18:39 2006: P[ 1]  $$$ CLEANUP CALLED pid:7
Wed Nov 22 00:18:39 2006: P[ 1]  $$$ Cleaning up bc with stid :10010100 pid:7
Wed Nov 22 00:18:39 2006: P[ 1]  ec_disable
Wed Nov 22 00:18:39 2006: P[ 1]  Sending Control ECHOCAN_OFF
Wed Nov 22 00:18:39 2006: P[ 1]  ph_control: c1:2319 c2:0
Wed Nov 22 00:18:39 2006: P[ 1]  I IND :RELEASE_COMPLETE oad: dad: pid:7 state:CLEANING
Wed Nov 22 00:18:39 2006: P[ 1]   --> channel:0 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 00:18:39 2006: P[ 1]   --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 00:18:39 2006: P[ 1]   --> addr:50010102 l3id:10042 b_stid:0 layer_id:50010180
Wed Nov 22 00:18:39 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 00:18:39 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 00:18:39 2006: P[ 1]  ast_hangup already called, so we have no ast ptr anymore in event(RELEASE_COMPLETE)
Wed Nov 22 00:18:39 2006: P[ 1]  hangup_chan
Wed Nov 22 00:18:39 2006: P[ 1]  No need to queue hangup
Wed Nov 22 00:18:39 2006: P[ 1]  Cannot hangup chan, no ast
Wed Nov 22 00:18:39 2006: P[ 1]  release_chan: bc with l3id: 10042
Wed Nov 22 00:18:39 2006: P[ 1]   --> Faking Realease_cr for 41000101
Wed Nov 22 00:18:39 2006: P[ 1]   --> lib: RELEASE_CR Ind with l3id:10042
Wed Nov 22 00:18:39 2006: P[ 1]   --> lib: CLEANING UP l3id: 10042
Wed Nov 22 00:18:39 2006: P[ 1]  $$$ CLEANUP CALLED pid:7
Wed Nov 22 00:18:39 2006: P[ 1]  BCHAN: MGR_DELLAYER|CNF pid:7
Wed Nov 22 00:18:44 2006: P[ 1]  % GOT L2 DeActivate Info.
Wed Nov 22 00:39:31 2006: P[ 1]  MGMT: SSTATUS: L1_ACTIVATED 
Wed Nov 22 00:39:31 2006: P[ 1]  L1: PH L1Link Up!
Wed Nov 22 01:40:31 2006: P[ 1]  MGMT: SSTATUS: L1_ACTIVATED 
Wed Nov 22 01:40:31 2006: P[ 1]  L1: PH L1Link Up!
Wed Nov 22 01:40:31 2006: P[ 1]  MGMT: SSTATUS: L1_ACTIVATED 
Wed Nov 22 01:40:31 2006: P[ 1]  L1: PH L1Link Up!
[I][B]Ein paar Stunden später dann ein Anruf von außen[/B][/I]
Wed Nov 22 22:11:54 2006: P[ 0]   --> * NEW CHANNEL dad:1234 oad:(null)
Wed Nov 22 22:11:54 2006: P[ 1]  * Queuing chan 0x8194680
Wed Nov 22 22:11:54 2006: P[ 1]   --> TON: Unknown
Wed Nov 22 22:11:54 2006: P[ 1]   --> LTON: Unknown
Wed Nov 22 22:11:54 2006: P[ 1]   --> CTON: Unknown
Wed Nov 22 22:11:54 2006: P[ 1]  * CALL: 1/1234
Wed Nov 22 22:11:54 2006: P[ 1]   --> * dad:1234 tech:mISDN/1-u1 ctx:outgoing
Wed Nov 22 22:11:54 2006: P[ 1]   --> * adding2newbc ext 1234
Wed Nov 22 22:11:54 2006: P[ 1]   --> * adding2newbc callerid 069123456
Wed Nov 22 22:11:54 2006: P[ 1]  update_config: Getting Config
Wed Nov 22 22:11:54 2006: P[ 1]   --> pres: -1 screen: -1
Wed Nov 22 22:11:54 2006: P[ 1]   --> pres: 0
Wed Nov 22 22:11:54 2006: P[ 1]   --> PRES: Allowed (0x0)
Wed Nov 22 22:11:54 2006: P[ 1]   --> SCREEN: Unscreened (0x0)
Wed Nov 22 22:11:54 2006: P[ 1]  NO OPTS GIVEN
Wed Nov 22 22:11:54 2006: P[ 1]  I SEND:SETUP oad:069123456 dad:1234 pid:9
Wed Nov 22 22:11:54 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 22:11:54 2006: P[ 1]   --> channel:0 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 22:11:54 2006: P[ 1]   --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> addr:0 l3id:8001ff00 b_stid:0 layer_id:50010180
Wed Nov 22 22:11:54 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 22:11:54 2006: P[ 1]  find_free_chan: req_chan:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> found chan: 1
Wed Nov 22 22:11:54 2006: P[ 1]   -->  found channel: 1
Wed Nov 22 22:11:54 2006: P[ 1]   --> new_l3id ff01
Wed Nov 22 22:11:54 2006: P[ 1]   --> * SEND: State Dialing pid:9
Wed Nov 22 22:11:54 2006: P[ 1]   --> lib: Event_ind:SETUP CONFIRM [NT] : new L3ID  is 8002ff01
Wed Nov 22 22:11:54 2006: P[ 1]  I IND :CC_SETUP|CONFIRM: old l3id:ff01 new l3id:8002ff01
Wed Nov 22 22:11:54 2006: P[ 1]  I IND :NEW_L3ID oad:069123456 dad:1234 pid:9 state:CALLING
Wed Nov 22 22:11:54 2006: P[ 1]   --> channel:1 mode:NT cause:16 ocause:16 rad: cad:
Wed Nov 22 22:11:54 2006: P[ 1]   --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 22:11:54 2006: P[ 1]   --> addr:0 l3id:8002ff01 b_stid:0 layer_id:50010180
Wed Nov 22 22:11:54 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 22:11:54 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 22:12:02 2006: P[ 1]  empty_chan_in_stack: 1
Wed Nov 22 22:12:02 2006: P[ 1]  $$$ CLEANUP CALLED pid:9
Wed Nov 22 22:12:02 2006: P[ 1]  I IND :RELEASE_COMPLETE oad: dad: pid:9 state:CALLING
Wed Nov 22 22:12:02 2006: P[ 1]   --> channel:0 mode:NT cause:18 ocause:16 rad: cad:
Wed Nov 22 22:12:02 2006: P[ 1]   --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0
Wed Nov 22 22:12:02 2006: P[ 1]   --> caps:Speech pi:0 keypad: sending_complete:0
Wed Nov 22 22:12:02 2006: P[ 1]   --> screen:0 --> pres:0
Wed Nov 22 22:12:02 2006: P[ 1]   --> addr:0 l3id:8002ff01 b_stid:0 layer_id:50010180
Wed Nov 22 22:12:02 2006: P[ 1]   --> facility:FAC_NONE out_facility:FAC_NONE
Wed Nov 22 22:12:02 2006: P[ 1]   --> bc_state:BCHAN_CLEANED
Wed Nov 22 22:12:02 2006: P[ 1]  hangup_chan
Wed Nov 22 22:12:02 2006: P[ 1]  -> queue_hangup
Wed Nov 22 22:12:02 2006: P[ 1]  release_chan: bc with l3id: 8002ff01
Wed Nov 22 22:12:02 2006: P[ 1]  * RELEASING CHANNEL pid:9 ctx:outgoing dad:1234 oad:sipgate state: CALLING
Wed Nov 22 22:12:02 2006: P[ 1]   --> * State Down
Wed Nov 22 22:12:02 2006: P[ 1]   --> Setting AST State to down

Wenn man jetzt intern abhebt und den Asterisk anwählt, dann kommt nichts; auch im Log nicht.
Will Asterisk über ISDN rufen bekommt es mode:NT cause:18 und legt auf...

Ein misdn show stacks zeigt das:

BEGIN STACK_LIST:
  * Port 1 Type NT Prot. PMP L2Link DOWN L1Link:UP Blocked:0  Debug:4

Ist L1Link fälschlich auf UP?
Kann es sein, dass der NTBA irgendwann abschaltet? (Ob er explizit mit Strom versorgt wird, oder über die ISTEC, macht keinen Unterschied im Resultat).
Kann es evtl. das gekreuzte Kabel sein?

Ich habe ein paar ähnliche Probleme bei anderen hier im Forum gefunden, aber da wurde es mit dem rc19 gelöst.

Danke vorab für die Mühe es zu lesen
und Grüße
bsel

 

[sterkel]

L1 up bedeutet lediglich, dass das Kabel eingesteckt ist. Wie sieht es denn mit den Interrupts aus?
Dieses "Einschlafen am Bus" gabs mal eine Zeit, sollte aber eigentlich erledigt sein.
Wenn die ISTEC den Strom liefert, müsste es doch auch nur mit dem gekreuzten Kabel gehen. Dann könntest Du den NTBA noch wegrationalisieren.

 

[bsel]

Direkt funktioniert nicht, dann bekommt er L1 nicht auf UP.

Ich habe letzten Monat auch alle APM Funktionen im BIOS ausgeschaltet. Müsste ich beim nächsten Reboot mal wieder an machen.

Die Karte beansprucht IRQ 12 für sich alleine.

lspci -v

0000:00:0b.0 Network controller: Cologne Chip Designs GmbH ISDN network controller [HFC-PCI] (rev 02)
        Subsystem: Cologne Chip Designs GmbH ISDN Board
        Flags: bus master, medium devsel, latency 16, IRQ 12
        I/O ports at d000 [disabled] [size=8]
        Memory at effffd00 (32-bit, non-prefetchable) [size=256]
        Capabilities: [40] Power Management version 1

cat /proc/interrupts

           CPU0
  0: 2768383887          XT-PIC  timer
  2:          0          XT-PIC  cascade
 10:    9633375          XT-PIC  eth1
 11:   10009954          XT-PIC  eth0
 12:     283702          XT-PIC  HFC PCI
 14:    2317922          XT-PIC  ide0
NMI:          0
LOC: 2768562537
ERR:    3207407
MIS:          0

Ürigens: Wenn das Problem auftritt und ich das gekreuzte Kabel ziehe, dann geht L1 nicht DOWN sondern bleibt UP.