[asterisk-users] zap fxo to sip fxs intermitently not connecting to each other

Tue Aug 29 18:43:59 MST 2006

Hi list,

On my asterisk based home pbx system, i have 1 zap interface(wildcard x100p) and 1 sipura 2000(which receiver is connected to) and some sip account  for my long distances and incoming calls.

When my call comes from SIP i've got no problem.  However when calls comes from zap, the zap interface picks up immediately(according to my extensions.conf) and I send it to my sipura via SIP.  Sipura rings the line, I pickup ... the two side doesn't get connected. The problem is reproducable.

When I look at the logs and compare it to the successfull  test cases everything looks normal. Zap pickup the line, gets forwarded to SIP, SIP rings, I pickup the sip phone.. nobody on the other side.. When the other side is me with my cellphone, cellphone keeps rining.

Does anybody have a slight idea of what the problem could be. OK Yes I am using a clone wildcard, but as you can see it does anwser. and Dial SIP which does ring.

This below is a sample of the logs when the problem was reproduced. And some SIP log available last.

Thanks

David

Aug 29 20:10:10 DEBUG[20159] chan_zap.c: Monitor doohicky got event Ring Begin on channel 1
Aug 29 20:10:12 DEBUG[20159] chan_zap.c: Monitor doohicky got event Ring/Answered on channel 1
Aug 29 20:10:12 DEBUG[20159] dsp.c: dsp busy pattern set to 0,0
Aug 29 20:10:12 DEBUG[20150] devicestate.c: Changing state for Zap/1 - state 2 (In use)
Aug 29 20:10:12 VERBOSE[20176] logger.c: Asterisk Ready.
    -- Starting simple switch on 'Zap/1-1'
Aug 29 20:10:12 DEBUG[20177] app_queue.c: Device 'Zap/1' changed to state '2' (In use)
Aug 29 20:10:16 NOTICE[20176] chan_zap.c: Got event 18 (Ring Begin)...
Aug 29 20:10:16 DEBUG[20176] pbx.c: Launching 'Wait'
Aug 29 20:10:16 VERBOSE[20176] logger.c:     -- Executing Wait("Zap/1-1", "1") in new stack
Aug 29 20:10:17 DEBUG[20176] pbx.c: Launching 'Answer'
Aug 29 20:10:17 VERBOSE[20176] logger.c:     -- Executing Answer("Zap/1-1", "") in new stack
Aug 29 20:10:17 DEBUG[20176] chan_zap.c: Took Zap/1-1 off hook
Aug 29 20:10:17 DEBUG[20150] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Aug 29 20:10:17 DEBUG[20176] chan_zap.c: Enabled echo cancellation on channel 1
Aug 29 20:10:17 DEBUG[20176] chan_zap.c: Engaged echo training on channel 1
Aug 29 20:10:17 DEBUG[20176] pbx.c: Launching 'Dial'
Aug 29 20:10:17 VERBOSE[20176] logger.c:     -- Executing Dial("Zap/1-1", "SIP/2201|40|r") in new stack
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Setting NAT on RTP to 0
Aug 29 20:10:17 DEBUG[20176] channel.c: Not copying variable STACK-default-s-3.
Aug 29 20:10:17 DEBUG[20176] channel.c: Not copying variable STACK-default-s-2.
Aug 29 20:10:17 DEBUG[20176] channel.c: Not copying variable STACK-default-s-1.
Aug 29 20:10:17 DEBUG[20176] channel.c: Not copying variable TRANSFERCAPABILITY. 
Aug 29 20:10:17 DEBUG[20150] devicestate.c: Changing state for Zap/1 - state 2 (In use)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Outgoing Call for 2201
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Updating call counter for outgoing call
Aug 29 20:10:17 VERBOSE[20176] logger.c: We're at 10.0.0.4 port 14962
Aug 29 20:10:17 VERBOSE[20176] logger.c: Adding codec 0x4 (ulaw) to SDP
Aug 29 20:10:17 VERBOSE[20176] logger.c: Adding codec 0x8 (alaw) to SDP
Aug 29 20:10:17 DEBUG[20178] app_queue.c: Device 'Zap/1' changed to state '2' (In use)
Aug 29 20:10:17 VERBOSE[20176] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 0: INVITE sip:2201 at 10.0.0.100:5060 SIP/2.0 (39)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK7d531cbe;rport (59)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 2: From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f (55)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 3: To: <sip:2201 at 10.0.0.100:5060> (30)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 4: Contact: <sip:asterisk at 10.0.0.4> (32)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 5: Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4 (50)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 8: Max-Forwards: 70 (16)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 9: Date: Wed, 30 Aug 2006 00:10:17 GMT (35)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOT
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 11: Content-Type: application/sdp (29)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 12: Content-Length: 232 (19)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Header 13:  (0)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Line: v=0 (3)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Line: o=root 20176 20176 IN IP4 10.0.0.4 (34)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Line: s=session (9)
Aug 29 20:10:17 DEBUG[20176] chan_sip.c: Line: c=IN IP4 10.0.0.4 (17)

SIP debug logs
---*CLI>     -- Starting simple switch on 'Zap/1-1'
Aug 29 20:10:16 NOTICE[20176]: chan_zap.c:6062 ss_thread: Got event 18 (Ring Begin)...
    -- Executing Wait("Zap/1-1", "1") in new stack
    -- Executing Answer("Zap/1-1", "") in new stack
    -- Executing Dial("Zap/1-1", "SIP/2201|40|r") in new stack
We're at 10.0.0.4 port 14962
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x8 (alaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
13 headers, 11 lines
Reliably Transmitting (no NAT) to 10.0.0.100:5060:
INVITE sip:2201 at 10.0.0.100:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK7d531cbe;rport
From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
To: <sip:2201 at 10.0.0.100:5060>
Contact: <sip:asterisk at 10.0.0.4>
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Wed, 30 Aug 2006 00:10:17 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 232

v=0
o=root 20176 20176 IN IP4 10.0.0.4
s=session
c=IN IP4 10.0.0.4
t=0 0
m=audio 14962 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
    -- Called 2201

<-- SIP read from 10.0.0.100:5060: 
SIP/2.0 100 Trying
To: <sip:2201 at 10.0.0.100:5060>
From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK7d531cbe
Server: Sipura/SPA2000-2.0.13(g)
Content-Length: 0

--- (8 headers 0 lines)---

<-- SIP read from 10.0.0.100:5060: 
SIP/2.0 180 Ringing
To: <sip:2201 at 10.0.0.100:5060>;tag=4cc2d203bb415c54i0
From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK7d531cbe
Server: Sipura/SPA2000-2.0.13(g)
Content-Length: 0

--- (8 headers 0 lines)---
    -- SIP/2201-e2ff is ringing

<-- SIP read from 10.0.0.100:5060: 
SIP/2.0 200 OK
To: <sip:2201 at 10.0.0.100:5060>;tag=4cc2d203bb415c54i0
From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK7d531cbe
Contact: <sip:2201 at 10.0.0.100:5060>
Server: Sipura/SPA2000-2.0.13(g)
Content-Length: 235
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura
Content-Type: application/sdp

v=0
o=- 267258876 267258876 IN IP4 10.0.0.100
s=-
c=IN IP4 10.0.0.100
t=0 0
m=audio 16474 RTP/AVP 0 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:100 NSE/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

--- (12 headers 12 lines)---
Found RTP audio format 0
Found RTP audio format 100
Found RTP audio format 101
Peer audio RTP is at port 10.0.0.100:16474
Found description format PCMU
Found description format NSE
Found description format telephone-event
Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
list_route: hop: <sip:2201 at 10.0.0.100:5060>
set_destination: Parsing <sip:2201 at 10.0.0.100:5060> for address/port to send to
set_destination: set destination to 10.0.0.100, port 5060
Transmitting (no NAT) to 10.0.0.100:5060:
ACK sip:2201 at 10.0.0.100:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.4:5060;branch=z9hG4bK1247594b;rport
From: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
To: <sip:2201 at 10.0.0.100:5060>;tag=4cc2d203bb415c54i0
Contact: <sip:asterisk at 10.0.0.4>
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
    -- SIP/2201-e2ff answered Zap/1-1

<-- SIP read from 10.0.0.100:5060: 
BYE sip:asterisk at 10.0.0.4 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.100:5060;branch=z9hG4bK-34b9681b
From: <sip:2201 at 10.0.0.100:5060>;tag=4cc2d203bb415c54i0
To: "asterisk" <sip:asterisk at 10.0.0.4>;tag=as3f09488f
Call-ID: 20c1d14300b5f9977c52bd593ee31568 at 10.0.0.4
CSeq: 101 BYE
Max-Forwards: 70
User-Agent: Sipura/SPA2000-2.0.13(g)
Content-Length: 0