Huge problem on a BRI, never seen something like that before (in fact I suspect a misconfiguration from the telco side). Situation: Asterisk box with cheap a HFCS card on DAHDI, the other side is an ‘emulated’ BRI from the provider router (some form of VoIP, Fastweb in Italy). The router is an Aethra SV6044E if it helps… Asterisk 14.0.2, DAHDI 2.11.1 patched with the HFC-S driver.
One SIP phone calling out to test. In short: call doesn’t get out 
(congestion tone)
in chan_dahdi I have:
; Span 1: DAHDI_HFCS_FKA_ZTHFC1 "HFC-S PCI A ISDN card 0 [TE] " (MASTER) AMI/CCS
group=0,11
context=from-pstn
switchtype = euroisdn
signalling = bri_cpe_ptp
channel => 1-2
Yes, it’s point to point! Layer 1 and 2 are coming up without issues, it seems… The dialplan is:
[citofono]
exten => 4445,1,Verbose(3,“Routing call using ISDN to ${ARG1}”)
same => n,Wait(${INITIAL_DELAY})
same => n,Dial(dahdi/g0/3282119763/sn,${DIAL_TIMEOUT},rtTkKXxWw)
same => n,Set(CDR(userfield)=Hangupcause:${HANGUPCAUSE})
same => n,Goto(sub-dial-response,s-${DIALSTATUS},1)
That’s a one-button phone which dial 4445 when you use it… 328…is the target phone for testing. A detailed ISDN trace is like this:
[Oct 24 15:06:20] DEBUG[917][C-00000001] pbx.c: Launching 'Dial'
[Oct 24 15:06:20] VERBOSE[917][C-00000001] pbx.c: Executing [4445@citofono:3] Dial("SIP/cito-00000000", "dahdi/g0/3282119763/sn,60,rtTkKXxWw") in new stack
[Oct 24 15:06:20] DEBUG[917][C-00000001] chan_dahdi.c: Using channel 1
[Oct 24 15:06:20] DEBUG[917][C-00000001] sig_pri.c: sig_pri_request 1
[Oct 24 15:06:20] DEBUG[917][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Oct 24 15:06:20] DEBUG[917][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Oct 24 15:06:20] DEBUG[755] devicestate.c: Changing state for DAHDI/i1/3282119763 - state 2 (In use)
[Oct 24 15:06:20] DEBUG[917][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001]
[Oct 24 15:06:20] DEBUG[917][C-00000001] rtp_engine.c: Can't find native functions for channel 'DAHDI/i1/3282119763-1'
[Oct 24 15:06:20] DEBUG[779] app_queue.c: Device 'DAHDI/i1/3282119763' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Oct 24 15:06:20] DEBUG[917][C-00000001] sig_pri.c: CALLER NAME: Citofono NUM: cito
– OK, thats only the channel opening and my debug statement… –
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 -- Making new call for cref 32769
[Oct 24 15:06:20] VERBOSE[917][C-00000001] sig_pri.c: Requested transfer capability: 0x00 - SPEECH
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=33
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Message Type: SETUP (5)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=0, window is open V(A)=0 K=7
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > V(A)=0, V(S)=0, V(R)=0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [ 00 01 00 00 08 02 00 01 05 04 03 80 90 a3 18 03 a1 83 81 6c 02 21 81 70 0b 80 33 32 38 32 31 31 39 37 36 33 a1 ]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Informational frame:
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > SAPI: 00 C/R: 0 EA: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI: 000 EA: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > N(S): 000 0: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > N(R): 000 P: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 -- Making new call for cref 32769
[Oct 24 15:06:20] VERBOSE[917][C-00000001] sig_pri.c: Requested transfer capability: 0x00 - SPEECH
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=33
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Message Type: SETUP (5)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=0, window is open V(A)=0 K=7
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > V(A)=0, V(S)=0, V(R)=0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [ 00 01 00 00 08 02 00 01 05 04 03 80 90 a3 18 03 a1 83 81 6c 02 21 81 70 0b 80 33 32 38 32 31 31 39 37 36 33 a1 ]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Informational frame:
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > SAPI: 00 C/R: 0 EA: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI: 000 EA: 1
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > N(S): 000 0: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > N(R): 000 P: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > 33 bytes of data
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=33
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Message Type: SETUP (5)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [04 03 80 90 a3]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Bearer Capability (len= 5) [ Ext: 1 Coding-Std: 0 Info transfer capability: Speech (0)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > User information layer 1: A-Law (35)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [18 03 a1 83 81]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Preferred Dchan: 0
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > ChanSel: As indicated in following octets
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Ext: 1 Coding: 0 Number Specified Channel Type: 3
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Ext: 1 Channel: 1 Type: CPE]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [6c 02 21 81]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Calling Party Number (len= 4) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Presentation: Presentation allowed, User-provided, verified and passed (1) '' ]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [70 0b 80 33 32 38 32 31 31 39 37 36 33]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Called Party Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '3282119763' ]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > [a1]
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 > Sending Complete (len= 1)
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 -- Stopping T203 timer
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 -- Starting T200 timer
[Oct 24 15:06:20] VERBOSE[917] chan_dahdi.c: PRI Span: 1 q931.c:6458 q931_setup: Call 32769 enters state 1 (Call Initiated). Hold state: Idle
[Oct 24 15:06:20] VERBOSE[917][C-00000001] app_dial.c: Called dahdi/g0/3282119763/sn
[Oct 24 15:06:20] DEBUG[917][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.3.202:5060
In my limited ISDN-knowledge this means that layer 2 is working and layer 3 it’s trying to come up with a call SETUP. Values seems reasonable to me…
…skip some SIP stuff for call progress…
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < V(A)=0, V(S)=1, V(R)=0
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < T200_id=8192, N200=3, T203_id=0
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < [ 00 01 01 02 ]
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < Supervisory frame:
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < SAPI: 00 C/R: 0 EA: 0
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < TEI: 000 EA: 1
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < N(R): 001 P/F: 0
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 < 0 bytes of data
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 -- Got ACK for N(S)=0 to (but not including) N(S)=1
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 -- ACKing N(S)=0, tx_queue head is N(S)=-1 (-1 is empty, -2 is not transmitted)
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 -- Stopping T200 timer
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 -- Starting T203 timer
[Oct 24 15:06:20] VERBOSE[768] chan_dahdi.c: PRI Span: 1 Done handling message for SAPI/TEI=0/0
Didn’t check the values but it’s presumably the L2 acknowledge for the SETUP call. So something is arrived to the router/ISDN emulator.
[Oct 24 15:06:24] VERBOSE[768] chan_dahdi.c: PRI Span: 1 T303 timed out. cref:32769
Ouch. My personal interpretation: the SETUP request was ignored and timed out (T303 at the default 4000 ms; tried to raise it, didn’t help). Next it retries the SETUP request (omitting…)
[Oct 24 15:06:28] VERBOSE[768] chan_dahdi.c: PRI Span: 1 T303 timed out. cref:32769
[Oct 24 15:06:28] VERBOSE[768] chan_dahdi.c: PRI Span: 1 q931.c:6344 t303_expiry: Call 32769 enters state 0 (Null). Hold state: Idle
[Oct 24 15:06:28] VERBOSE[768] chan_dahdi.c: PRI Span: 1 Fake clearing. cref:32769
[Oct 24 15:06:28] VERBOSE[768] chan_dahdi.c: PRI Span: 1 q931.c:9837 pri_internal_clear: alive 1, hangupack 1
[Oct 24 15:06:28] VERBOSE[768] sig_pri.c: Span 1: Processing event PRI_EVENT_HANGUP(6)
[Oct 24 15:06:28] VERBOSE[768][C-00000001] sig_pri.c: Span 1: Channel 0/1 got hangup, cause 18
[Oct 24 15:06:28] DEBUG[917][C-00000001] channel.c: Hanging up channel 'DAHDI/i1/3282119763-1'
[Oct 24 15:06:28] DEBUG[917][C-00000001] chan_dahdi.c: dahdi_hangup(DAHDI/i1/3282119763-1)
My interpretation: asterisk decided the call isn’t getting thru and does a disconnect.
Now, the tech support of Fastweb is highly unhelpful (they checked the interdigit timeout for an INCOMING call, one time). Is there something I could try to make the system go? Have I misinterpreted something?
Inbound calls don’t work, too, by the way… (times out waiting for CONNECT acknowledge).