Timeout on Ringing

Asterisk Asterisk Support
1

Hi All,

we have a small problem during Dial from an asterisk server with a trunk SIP (we use a cisco SIP trunk to do our tests). We set the ringing timeout to 45 sec but the ringing stop at 30 sec. When we answer, the communication continue normally and every thing is ok. The ringing timeout works if we set a value lower than 30 sec but we would like to set a greater value.

We have read that it could be a NAT problem but we just use a SIP Proxy (Kamalio) and asterisk has a publically addressable IP.

We use asterisk 1.8.17.0

Here is a SIP debug :

INVITE sip:00582743866@10.1.9.5 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
To: <sip:00582743866@10.1.9.5>
Contact: <sip:0123456789@10.1.3.233:5060>
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.17.0
Date: Tue, 28 May 2013 07:27:49 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 231

v=0
o=root 204944793 204944793 IN IP4 10.1.3.233
s=Asterisk PBX 1.8.17.0
c=IN IP4 10.1.3.233
t=0 0
m=audio 16486 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---



<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport=5060
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
To: <sip:00582743866@10.1.9.5>
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
CSeq: 102 INVITE
Server: kamailio (3.3.0 (x86_64/linux))
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---


<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 183 Session Progress
Date: Tue, 28 May 2013 07:32:22 GMT
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
Allow-Events: telephone-event
Supported: sdp-anat
Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
Content-Length: 179
To: <sip:00582743866@10.1.9.5>;tag=D0C52F2C-1FEC
Contact: <sip:00582743866@10.1.9.5:5060>
C

Content-Type: application/sdp
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport=5060
CSeq: 102 INVITE
Server: Cisco-SIPGateway/IOS-12.x
Record-Route: <sip:10.1.3.240;lr=on>

v=0
o=CiscoSystemsSIP-GW-UserAgent 7232 6826 IN IP4 10.1.9.5
s=SIP Call
c=IN IP4 10.1.9.5
t=0 0
m=audio 17098 RTP/AVP 0
c=IN IP4 10.1.9.5
a=rtpmap:0 PCMU/8000
a=ptime:20
<------------->



Found RTP audio format 0
Found audio description format PCMU for ID 0
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing)
Peer audio RTP is at port 10.1.9.5:17098


<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 183 Session Progress
Date: Tue, 28 May 2013 07:32:22 GMT
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
Allow-Events: telephone-event
Supported: sdp-anat
Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
Content-Length: 179
To: <sip:00582743866@10.1.9.5>;tag=D0C52F2C-1FEC
Contact: <sip:00582743866@10.1.9.5:5060>
C

Content-Type: application/sdp
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport=5060
CSeq: 102 INVITE
Server: Cisco-SIPGateway/IOS-12.x
Record-Route: <sip:10.1.3.240;lr=on>

v=0
o=CiscoSystemsSIP-GW-UserAgent 7232 6826 IN IP4 10.1.9.5
s=SIP Call
c=IN IP4 10.1.9.5
t=0 0
m=audio 17098 RTP/AVP 0
c=IN IP4 10.1.9.5
a=rtpmap:0 PCMU/8000
a=ptime:20
<------------->

list_route: hop: <sip:10.1.3.240;lr=on>
    -- SIP/cisco-000000ce is making progress passing it to Local/s@dso-command-00002a7d;2



OPTIONS sip:10.1.3.240 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK3d7d9839;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.1.3.233>;tag=as55bed21d
To: <sip:10.1.3.240>
Contact: <sip:asterisk@10.1.3.233:5060>
Call-ID: 75b4b24424b79ed77a61b9931ceafcde@10.1.3.233:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.8.17.0
Date: Tue, 28 May 2013 07:28:14 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 484 Address Incomplete
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK3d7d9839;rport=5060
From: "asterisk" <sip:asterisk@10.1.3.233>;tag=as55bed21d
To: <sip:10.1.3.240>;tag=b27e1a1d33761e85846fc98f5f3a7e58.dd62
Call-ID: 75b4b24424b79ed77a61b9931ceafcde@10.1.3.233:5060
CSeq: 102 OPTIONS
Server: kamailio (3.3.0 (x86_64/linux))
Content-Length: 0

<------------->

Really destroying SIP dialog '75b4b24424b79ed77a61b9931ceafcde@10.1.3.233:5060' Method: OPTIONS


OPTIONS sip:10.1.9.5 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK4eb93c1b;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.1.3.233>;tag=as6e2ee137
To: <sip:10.1.9.5>
Contact: <sip:asterisk@10.1.3.233:5060>
Call-ID: 1796e674563be7cb40eaf7bb3123a7d2@10.1.3.233:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.8.17.0
Date: Tue, 28 May 2013 07:28:14 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH


Content-Length: 0


---

SIP/2.0 200 OK
Date: Tue, 28 May 2013 07:32:46 GMT
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
From: "asterisk" <sip:asterisk@10.1.3.233>;tag=as6e2ee137
Allow-Events: telephone-event
Supported: 100rel,resource-priority,replaces,sdp-anat
Content-Length: 157
To: <sip:10.1.9.5>;tag=D0C58E60-1A1D
Content-Type: application/sdp
Call-ID: 1796e674563be7cb40eaf7bb3123a7d2@10.1.3.233:5060
Accept: application/sdp
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK4eb93c1b;rport
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 OPTIONS

v=0
o=CiscoSystemsSIP-GW-UserAgent 5489 5914 IN IP4 10.1.9.5
s=SIP Call
c=IN IP4 10.1.9.5
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3
c=IN IP4 10.1.9.5
<------------->
--- (14 headers 7 lines) ---
Really destroying SIP dialog '1796e674563be7cb40eaf7bb3123a7d2@10.1.3.233:5060' Method: OPTIONS


CANCEL sip:00582743866@10.1.9.5 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
To: <sip:00582743866@10.1.9.5>
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 1.8.17.0
Content-Length: 0

<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 200 canceling
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport=5060
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
To: <sip:00582743866@10.1.9.5>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-2a48
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
CSeq: 102 CANCEL
Server: kamailio (3.3.0 (x86_64/linux))
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

P read from UDP:10.1.3.240:5060 --->
SIP/2.0 487 Request Cancelled
Reason: Q.850;cause=16
Date: Tue, 28 May 2013 07:32:51 GMT
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
Allow-Events: telephone-event
Content-Length: 0
To: <sip:00582743866@10.1.9.5>;tag=D0C52F2C-1FEC
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport=5060
CSeq: 102 INVITE
Server: Cisco-SIPGateway/IOS-12.x

<------------->


Transmitting (NAT) to 10.1.3.240:5060:
ACK sip:00582743866@10.1.9.5:5060 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK1121c8b3;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as087c91b7
To: <sip:00582743866@10.1.9.5>;tag=D0C52F2C-1FEC
Contact: <sip:0123456789@10.1.3.233:5060>
Call-ID: 793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.8.17.0
Content-Length: 0
---

e[KcvgVMasterisk1*CLI> 
e[0KScheduling destruction of SIP dialog '793ea1960b6db6961d64db3618655a7c@10.1.3.233:5060' in 12800 ms (Method: INVITE)

and the sip.conf file

[general]
context=incoming-sip                 
udpbindaddr=10.1.3.233                                
tcpenable=no                    
tcpbindaddr=0.0.0.0             
srvlookup=yes                   
qualify=yes
disallow=all                   
allow=ulaw                     
outboundproxy=10.1.3.240
t1min=200                      
timert1=700                    
timerb=45000                   
rtptimeout=60                  
rtpholdtimeout=300             
rtpkeepalive=15            
allowsubscribe=no              
directmedia=no
[authentication]

[basic-options](!)                
        dtmfmode=rfc2833
        context=from-office
        type=friend

[natted-phone](!,basic-options)   
        nat=yes
        directmedia=no
        host=dynamic

[public-phone](!,basic-options)   
        nat=no
        directmedia=yes

[my-codecs](!)                    
        disallow=all
        allow=ilbc
        allow=g729
        allow=gsm
        allow=g723
        allow=ulaw

[ulaw-phone](!)                   
        disallow=all
        allow=ulaw

#include </etc/asterisk/peers/*.conf>

Thanks

Eric

2

The trace shows an unanswered call, terminated by Asterisk, after an unknown amount of time. It looks like a screen scrape, and thus is lacking the time information in the logs. There is not enough information to work out why Asterisk cancelled.

The call probably had early media as it has 183, rather than 180.

You failed to include /etc/asterisk/peers/*.conf, which is logically part of sip.conf. I wasn’t aware a wildcard was allowed.

3

thank your for your answer,

here is the full trace with timestamps and debug informations


e[0;37me[0mConnected to Asterisk 1.8.17.0 currently running on cvgVMasterisk1 (pid = 24118)
cvgVMasterisk1*CLI> 
e[0KVerbosity is at least 1

e[KcvgVMasterisk1*CLI> 
e[0KCore debug is at least 4


e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m682e[0m e[1;37mhandle_urie[0m: HTTP Request URI is /rawman?Archive=yes&Extension=s&Channel=Local%2Fs%40dso-command%2Fn&Context=dso-event-answer&Callerid=411924221&RetryTime=300&Maxretries=0&WaitTime=60&action=originate&async=true&Priority=1&variable=CALL_HIDDEN=0,DSO_CALL_ID=411924221,DSO_REQUEST_ID=-3582203744243642322,DSO_CALLERID_NUM=%2B33689895897,DSO_TIMEOUT=48,DSO_PEER_NAME=cisco,DSO_NUMBER=00582743866,DSO_COMMAND=startcall 
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [httpstatus] len 0
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [phoneprov] len 10
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [amanager] len 9
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [arawman] len 8
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [manager] len 7
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m731e[0m e[1;37mhandle_urie[0m: match request [rawman] with handler [rawman] len 7
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mhttp.ce[0m:e[1;37m826e[0m e[1;37mparse_cookiese[0m: HTTP Cookie, Name: 'mansession_id'  Value: '35e7a4e2'
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Archive: yes
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Extension: s
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Channel: Local/s@dso-command/n
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Context: dso-event-answer
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Callerid: 411924221
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header RetryTime: 300
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Maxretries: 0
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header WaitTime: 60
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header action: originate
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header async: true
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header Priority: 1
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m5910e[0m e[1;37mgeneric_http_callbacke[0m: HTTP Manager add header variable: CALL_HIDDEN=0,DSO_CALL_ID=411924221,DSO_REQUEST_ID=-3582203744243642322,DSO_CALLERID_NUM=+33689895897,DSO_TIMEOUT=48,DSO_PEER_NAME=cisco,DSO_NUMBER=00582743866,DSO_COMMAND=startcall
[2013-05-30 17:17:26.798] e[1;32mDEBUGe[0m[24536]: e[1;37mmanager.ce[0m:e[1;37m4709e[0m e[1;37mprocess_messagee[0m: Running action 'Originate'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Set'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Set'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'NoOp'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'NoOp'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'NoOp'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'NoOp'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4075e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Function result is '0'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.799] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4143e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Expression result is '0'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.800] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'GotoIf'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:26.800] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'AGI'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.215] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Macro'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Set'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mapp_macro.ce[0m:e[1;37m435e[0m e[1;37m_macro_exece[0m: Executed application: Set
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4143e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Expression result is '0'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'ExecIf'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mapp_macro.ce[0m:e[1;37m435e[0m e[1;37m_macro_exece[0m: Executed application: ExecIf
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m3934e[0m e[1;37mast_str_substitute_variables_fulle[0m: Expression result is '0'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4143e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Expression result is '0'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'ExecIf'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mapp_macro.ce[0m:e[1;37m435e[0m e[1;37m_macro_exece[0m: Executed application: ExecIf
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m3934e[0m e[1;37mast_str_substitute_variables_fulle[0m: Expression result is '0'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'MacroExit'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Set'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Set'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'SIPAddHeader'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m29715e[0m e[1;37msip_addheadere[0m: SIP Header added "X-THECALLR-CUSTOM1: 411924221" as __SIPADDHEADER01

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4075e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Function result is '(null)'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'MixMonitor'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mautochan.ce[0m:e[1;37m58e[0m e[1;37mast_autochan_setupe[0m: Created autochan 0x1bc8d60 to hold channel Local/s@dso-command-0000000a;2 (0x1be3168)

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'Dial'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24540]: e[1;37maudiohook.ce[0m:e[1;37m233e[0m e[1;37maudiohook_read_frame_bothe[0m: Read factory 0x1bd7870 and write factory 0x1bd82b0 both fail to provide 160 samples
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m26733e[0m e[1;37msip_request_calle[0m: Asked to create a SIP channel with formats: 0x40 (slin)
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7861e[0m e[1;37msip_alloce[0m: Allocating new SIP dialog for 1052590842a692b36c0b6559023a52d9@10.1.3.233:5060 - INVITE (No RTP)
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mrtp_engine.ce[0m:e[1;37m350e[0m e[1;37mast_rtp_instance_newe[0m: Using engine 'asterisk' for RTP instance '0x7fd8d853c6a8'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m557e[0m e[1;37mast_rtp_newe[0m: Allocated port 17880 for RTP instance '0x7fd8d853c6a8'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mrtp_engine.ce[0m:e[1;37m359e[0m e[1;37mast_rtp_instance_newe[0m: RTP instance '0x7fd8d853c6a8' is setup and ready to go
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m2538e[0m e[1;37mast_rtp_prop_sete[0m: Setup RTCP on RTP instance '0x7fd8d853c6a8'
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m5158e[0m e[1;37mdo_setnate[0m: Setting NAT on RTP to Off
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3193e[0m e[1;37mobproxy_gete[0m: OBPROXY: Applying global OBproxy to this call
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37macl.ce[0m:e[1;37m736e[0m e[1;37mast_ouraddrfore[0m: For destination '10.1.9.5', our source address is '10.1.9.233'.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3551e[0m e[1;37mast_sip_ouraddrfore[0m: Setting SIP_TRANSPORT_UDP with address 10.1.3.233:5060
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7157e[0m e[1;37msip_newe[0m: *** Our native formats are 0x4 (ulaw) 
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7158e[0m e[1;37msip_newe[0m: *** Joint capabilities are 0x0 (nothing) 
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7159e[0m e[1;37msip_newe[0m: *** Our capabilities are 0x4 (ulaw) 
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7160e[0m e[1;37msip_newe[0m: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7162e[0m e[1;37msip_newe[0m: *** Our preferred formats from the incoming channel are 0x40 (slin) 
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m7190e[0m e[1;37msip_newe[0m: This channel will not be able to handle video.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DIALEDTIME.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable ANSWEREDTIME.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DIALEDPEERNAME.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DIALEDPEERNUMBER.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DIALSTATUS.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable MIXMONITOR_FILENAME.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6177e[0m e[1;37mast_channel_inherit_variablese[0m: Copying hard-transferable variable SIPADDHEADER01.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable MACRO_DEPTH.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_AGI_STATUS.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable AGISTATUS.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable AGISIGHUP.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable CALL_HIDDEN.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_CALL_ID.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_REQUEST_ID.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_CALLERID_NUM.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_TIMEOUT.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_PEER_NAME.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_NUMBER.
[2013-05-30 17:17:27.216] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m6181e[0m e[1;37mast_channel_inherit_variablese[0m: Not copying variable DSO_COMMAND.
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m5700e[0m e[1;37msip_calle[0m: Outgoing Call for 00582743866
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m5971e[0m e[1;37mupdate_call_countere[0m: Updating call counter for outgoing call
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m12399e[0m e[1;37mtransmit_invitee[0m: Adding SIP Header "X-THECALLR-CUSTOM1" with content :411924221: 
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m11480e[0m e[1;37madd_sdpe[0m: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m11481e[0m e[1;37madd_sdpe[0m: ** Our prefcodec: 0x40 (slin) 
Audio is at 17880
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m11590e[0m e[1;37madd_sdpe[0m: -- Done with adding codecs to SDP
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m11776e[0m e[1;37madd_sdpe[0m: Done building SDP. Settling with this capability: 0x4 (ulaw)
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3075e[0m e[1;37minitialize_initreqe[0m: Initializing initreq for method INVITE - callid 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 39]: INVITE sip:00582743866@10.1.9.5 SIP/2.0
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 61]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 16]: Max-Forwards: 70
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 30]: To: <sip:00582743866@10.1.9.5>
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 41]: Contact: <sip:0123456789@10.1.3.233:5060>
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 16]: CSeq: 102 INVITE
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  8 [ 33]: User-Agent: Asterisk PBX 1.8.17.0
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  9 [ 35]: Date: Thu, 30 May 2013 15:17:27 GMT
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 11 [ 26]: Supported: replaces, timer
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 12 [ 29]: X-THECALLR-CUSTOM1: 411924221
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 13 [ 29]: Content-Type: application/sdp
Reliably Transmitting (NAT) to 10.1.9.5:5060:
INVITE sip:00582743866@10.1.9.5 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
To: <sip:00582743866@10.1.9.5>
Contact: <sip:0123456789@10.1.3.233:5060>
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.17.0
Date: Thu, 30 May 2013 15:17:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
X-THECALLR-CUSTOM1: 411924221
Content-Type: application/sdp
Content-Length: 231

v=0
o=root 208393058 208393058 IN IP4 10.1.3.233
s=Asterisk PBX 1.8.17.0
c=IN IP4 10.1.3.233
t=0 0
m=audio 17880 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3854e[0m e[1;37m__sip_reliable_xmite[0m: *** SIP TIMER: Initializing retransmit timer on packet: Id  #197
[2013-05-30 17:17:27.217] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3399e[0m e[1;37m__sip_xmite[0m: Trying to put 'INVITE sip:' onto UDP socket destined for 10.1.3.240:5060

e[KcvgVMasterisk1*CLI> 
e[0K
<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
To: <sip:00582743866@10.1.9.5>
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
CSeq: 102 INVITE
Server: kamailio (3.3.0 (x86_64/linux))
Content-Length: 0

<------------->
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 50]: SIP/2.0 100 trying -- your call is important to us
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 66]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 30]: To: <sip:00582743866@10.1.9.5>

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 16]: CSeq: 102 INVITE

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 39]: Server: kamailio (3.3.0 (x86_64/linux))
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 17]: Content-Length: 0
--- (8 headers 0 lines) ---

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4117e[0m e[1;37m__sip_semi_acke[0m: *** SIP TIMER: Cancelling retransmission #197 - INVITE (got response)

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4124e[0m e[1;37m__sip_semi_acke[0m: (Provisional) Stopping retransmission (but retaining packet) on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' Request 102: Found
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m20169e[0m e[1;37mhandle_response_invitee[0m: SIP response 100 to standard invite

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m342e[0m e[1;37m_ast_device_statee[0m: No provider found, checking channel drivers for Local - s@dso-command
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24124]: e[1;37mchan_local.ce[0m:e[1;37m302e[0m e[1;37mlocal_devicestatee[0m: Checking if extension s@dso-command exists (devicestate)
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m460e[0m e[1;37mdo_state_changee[0m: Changing state for Local/s@dso-command - state 2 (In use)
[2013-05-30 17:17:27.218] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m440e[0m e[1;37mdevstate_evente[0m: device 'Local/s@dso-command' state '2'

e[KcvgVMasterisk1*CLI> 
e[0K
<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 183 Session Progress
Date: Thu, 30 May 2013 15:22:07 GMT
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
Allow-Events: telephone-event
Supported: sdp-anat
Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
Content-Length: 179
To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
Contact: <sip:00582743866@10.1.9.5:5060>
Content-Disposition: session;handling=required
Content-Type: application/sdp
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
CSeq: 102 INVITE
Server: Cisco-SIPGateway/IOS-12.x
Record-Route: <sip:10.1.3.240;lr=on>

v=0
o=CiscoSystemsSIP-GW-UserAgent 2059 4415 IN IP4 10.1.9.5
s=SIP Call
c=IN IP4 10.1.9.5
t=0 0
m=audio 16626 RTP/AVP 0
c=IN IP4 10.1.9.5
a=rtpmap:0 PCMU/8000
a=ptime:20
<------------->
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 28]: SIP/2.0 183 Session Progress
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 35]: Date: Thu, 30 May 2013 15:22:07 GMT
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 29]: Allow-Events: telephone-event
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 19]: Supported: sdp-anat
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 78]: Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 19]: Content-Length: 179
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  8 [ 46]: To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  9 [ 40]: Contact: <sip:00582743866@10.1.9.5:5060>
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 10 [ 46]: Content-Disposition: session;handling=required
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 11 [ 29]: Content-Type: application/sdp
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 12 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 13 [ 66]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 14 [ 16]: CSeq: 102 INVITE
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 15 [ 33]: Server: Cisco-SIPGateway/IOS-12.x
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 16 [ 36]: Record-Route: <sip:10.1.3.240;lr=on>
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 17 [  0]: 
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  0 [  3]: v=0
[2013-05-30 17:17:27.254] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  1 [ 56]: o=CiscoSystemsSIP-GW-UserAgent 2059 4415 IN IP4 10.1.9.5
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  2 [ 10]: s=SIP Call
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  3 [ 17]: c=IN IP4 10.1.9.5
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  4 [  5]: t=0 0
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  5 [ 23]: m=audio 16626 RTP/AVP 0
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  6 [ 17]: c=IN IP4 10.1.9.5
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8624e[0m e[1;37mparse_requeste[0m:    Body  8 [ 10]: a=ptime:20

e[KcvgVMasterisk1*CLI> 
e[0K--- (17 headers 9 lines) ---
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4124e[0m e[1;37m__sip_semi_acke[0m: (Provisional) Stopping retransmission (but retaining packet) on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' Request 102: Found
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m20169e[0m e[1;37mhandle_response_invitee[0m: SIP response 183 to standard invite
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m14373e[0m e[1;37mbuild_routee[0m: build_route: Record-Route hop: <sip:10.1.3.240;lr=on>
list_route: hop: <sip:10.1.3.240;lr=on>
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 2059 4415 IN IP4 10.1.9.5... UNSUPPORTED OR FAILED.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP c=IN IP4 10.1.9.5... OK.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
Found RTP audio format 0
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mrtp_engine.ce[0m:e[1;37m541e[0m e[1;37mast_rtp_codecs_payloads_set_m_typee[0m: Setting payload 0 based on m type on 0x7fd8c39b6ae0
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9246e[0m e[1;37mprocess_sdpe[0m: Processing media-level (audio) SDP c=IN IP4 10.1.9.5... OK.
Found audio description format PCMU for ID 0
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9246e[0m e[1;37mprocess_sdpe[0m: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9246e[0m e[1;37mprocess_sdpe[0m: Processing media-level (audio) SDP a=ptime:20... OK.
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mrtp_engine.ce[0m:e[1;37m644e[0m e[1;37mast_rtp_codecs_payload_formatse[0m: Incorporating payload 0 on 0x7fd8c39b6ae0
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing)
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m2578e[0m e[1;37mast_rtp_remote_address_sete[0m: Setting RTCP address on RTP instance '0x7fd8d853c6a8'
Peer audio RTP is at port 10.1.9.5:16626
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mrtp_engine.ce[0m:e[1;37m522e[0m e[1;37mast_rtp_codecs_payloads_copye[0m: Copying payload 0 from 0x7fd8c39b6ae0 to 0x7fd8d853c870
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m2504e[0m e[1;37mast_rtp_prop_sete[0m: Ignoring duplicate RTCP property on RTP instance '0x7fd8d853c6a8'
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9491e[0m e[1;37mprocess_sdpe[0m: We're settling with these formats: 0x4 (ulaw)
[2013-05-30 17:17:27.255] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9496e[0m e[1;37mprocess_sdpe[0m: We have an owner, now see if we need to change this call

e[KcvgVMasterisk1*CLI> 
e[0K
<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 183 Session Progress
Date: Thu, 30 May 2013 15:22:07 GMT
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
Allow-Events: telephone-event
Supported: sdp-anat
Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
Content-Length: 179
To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
Contact: <sip:00582743866@10.1.9.5:5060>
Content-Disposition: session;handling=required
Content-Type: application/sdp
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
CSeq: 102 INVITE
Server: Cisco-SIPGateway/IOS-12.x
Record-Route: <sip:10.1.3.240;lr=on>

v=0
o=CiscoSystemsSIP-GW-UserAgent 2059 4415 IN IP4 10.1.9.5
s=SIP Call
c=IN IP4 10.1.9.5
t=0 0
m=audio 16626 RTP/AVP 0
c=IN IP4 10.1.9.5
a=rtpmap:0 PCMU/8000
a=ptime:20
<------------->
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 28]: SIP/2.0 183 Session Progress
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 35]: Date: Thu, 30 May 2013 15:22:07 GMT
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 29]: Allow-Events: telephone-event
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 19]: Supported: sdp-anat
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 78]: Remote-Party-ID: <sip:00582743866@10.1.9.5>;party=called;screen=no;privacy=off
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 19]: Content-Length: 179
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  8 [ 46]: To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  9 [ 40]: Contact: <sip:00582743866@10.1.9.5:5060>
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 10 [ 46]: Content-Disposition: session;handling=required
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 11 [ 29]: Content-Type: application/sdp
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 12 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 13 [ 66]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 14 [ 16]: CSeq: 102 INVITE
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 15 [ 33]: Server: Cisco-SIPGateway/IOS-12.x
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 16 [ 36]: Record-Route: <sip:10.1.3.240;lr=on>
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 17 [  0]: 
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  0 [  3]: v=0
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  1 [ 56]: o=CiscoSystemsSIP-GW-UserAgent 2059 4415 IN IP4 10.1.9.5
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  2 [ 10]: s=SIP Call
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  3 [ 17]: c=IN IP4 10.1.9.5
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  4 [  5]: t=0 0
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  5 [ 23]: m=audio 16626 RTP/AVP 0
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  6 [ 17]: c=IN IP4 10.1.9.5
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8624e[0m e[1;37mparse_requeste[0m:    Body  8 [ 10]: a=ptime:20
--- (17 headers 9 lines) ---
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4124e[0m e[1;37m__sip_semi_acke[0m: (Provisional) Stopping retransmission (but retaining packet) on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' Request 102: Found
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m20169e[0m e[1;37mhandle_response_invitee[0m: SIP response 183 to standard invite
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m14373e[0m e[1;37mbuild_routee[0m: build_route: Record-Route hop: <sip:10.1.3.240;lr=on>
list_route: hop: <sip:10.1.3.240;lr=on>
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8974e[0m e[1;37mprocess_sdpe[0m: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2013-05-30 17:17:28.333] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m9601e[0m e[1;37mprocess_sdp_oe[0m: Call 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060 responded to our reinvite without changing SDP version; ignoring SDP.

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:29.877] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m1808e[0m e[1;37mast_rtcp_reade[0m: Got RTCP report of 84 bytes

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:33.145] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m1808e[0m e[1;37mast_rtcp_reade[0m: Got RTCP report of 84 bytes

e[KcvgVMasterisk1*CLI> 
e[0K
<--- SIP read from UDP:10.1.3.234:5060 --->
OPTIONS sip:10.1.3.233 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.234:5060;branch=z9hG4bK2c5c279c;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.1.3.234>;tag=as61c6eafb
To: <sip:10.1.3.233>
Contact: <sip:asterisk@10.1.3.234:5060>
Call-ID: 4ca36bce1075692b67c74c165cdb9029@10.1.3.234:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.8.17.0
Date: Thu, 30 May 2013 15:19:54 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------->
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 30]: OPTIONS sip:10.1.3.233 SIP/2.0
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 61]: Via: SIP/2.0/UDP 10.1.3.234:5060;branch=z9hG4bK2c5c279c;rport
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 16]: Max-Forwards: 70
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 57]: From: "asterisk" <sip:asterisk@10.1.3.234>;tag=as61c6eafb
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 20]: To: <sip:10.1.3.233>
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 39]: Contact: <sip:asterisk@10.1.3.234:5060>
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 57]: Call-ID: 4ca36bce1075692b67c74c165cdb9029@10.1.3.234:5060
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 17]: CSeq: 102 OPTIONS
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  8 [ 33]: User-Agent: Asterisk PBX 1.8.17.0
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  9 [ 35]: Date: Thu, 30 May 2013 15:19:54 GMT
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 11 [ 26]: Supported: replaces, timer
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 12 [ 17]: Content-Length: 0
--- (13 headers 0 lines) ---
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37macl.ce[0m:e[1;37m736e[0m e[1;37mast_ouraddrfore[0m: For destination '10.1.3.234', our source address is '10.1.3.233'.
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m3551e[0m e[1;37mast_sip_ouraddrfore[0m: Setting SIP_TRANSPORT_UDP with address 10.1.3.233:5060
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m7861e[0m e[1;37msip_alloce[0m: Allocating new SIP dialog for 4ca36bce1075692b67c74c165cdb9029@10.1.3.234:5060 - OPTIONS (No RTP)

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m25325e[0m e[1;37mhandle_incominge[0m: **** Received OPTIONS (3) - Command in SIP OPTIONS
Looking for s in incoming-sip (domain 10.1.3.233)

<--- Transmitting (NAT) to 10.1.3.234:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 10.1.3.234:5060;branch=z9hG4bK2c5c279c;received=10.1.3.234;rport=5060
From: "asterisk" <sip:asterisk@10.1.3.234>;tag=as61c6eafb
To: <sip:10.1.3.233>;tag=as7cdb02aa
Call-ID: 4ca36bce1075692b67c74c165cdb9029@10.1.3.234:5060
CSeq: 102 OPTIONS
Server: Asterisk PBX 1.8.17.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Accept: application/sdp
Content-Length: 0


<------------>
[2013-05-30 17:17:37.623] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m3399e[0m e[1;37m__sip_xmite[0m: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.1.3.234:5060
Scheduling destruction of SIP dialog '4ca36bce1075692b67c74c165cdb9029@10.1.3.234:5060' in 32000 ms (Method: OPTIONS)

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:39.766] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m1808e[0m e[1;37mast_rtcp_reade[0m: Got RTCP report of 84 bytes

e[KcvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:46.046] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m1808e[0m e[1;37mast_rtcp_reade[0m: Got RTCP report of 84 bytes

e[KcvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
cvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:51.655] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m1808e[0m e[1;37mast_rtcp_reade[0m: Got RTCP report of 84 bytes

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24537]: e[1;37mchannel.ce[0m:e[1;37m2873e[0m e[1;37mast_hangupe[0m: Hanging up channel 'Local/s@dso-command-0000000a;1'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m342e[0m e[1;37m_ast_device_statee[0m: No provider found, checking channel drivers for Local - s@dso-command
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mchan_local.ce[0m:e[1;37m302e[0m e[1;37mlocal_devicestatee[0m: Checking if extension s@dso-command exists (devicestate)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m2873e[0m e[1;37mast_hangupe[0m: Hanging up channel 'SIP/cisco-00000004'
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m460e[0m e[1;37mdo_state_changee[0m: Changing state for Local/s@dso-command - state 1 (Not in use)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m440e[0m e[1;37mdevstate_evente[0m: device 'Local/s@dso-command' state '1'
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m6353e[0m e[1;37msip_hangupe[0m: Hangup call SIP/cisco-00000004, SIP callid 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m6372e[0m e[1;37msip_hangupe[0m: Hanging up channel in state Down (not UP)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mres_rtp_asterisk.ce[0m:e[1;37m2578e[0m e[1;37mast_rtp_remote_address_sete[0m: Setting RTCP address on RTP instance '0x7fd8d853c6a8'
Scheduling destruction of SIP dialog '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' in 12800 ms (Method: INVITE)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m4124e[0m e[1;37m__sip_semi_acke[0m: (Provisional) Stopping retransmission (but retaining packet) on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' Request 102: Found
Reliably Transmitting (NAT) to 10.1.3.240:5060:
CANCEL sip:00582743866@10.1.9.5 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
To: <sip:00582743866@10.1.9.5>
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 1.8.17.0
Content-Length: 0


---
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3854e[0m e[1;37m__sip_reliable_xmite[0m: *** SIP TIMER: Initializing retransmit timer on packet: Id  #202
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchan_sip.ce[0m:e[1;37m3399e[0m e[1;37m__sip_xmite[0m: Trying to put 'CANCEL sip:' onto UDP socket destined for 10.1.3.240:5060
Scheduling destruction of SIP dialog '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' in 12800 ms (Method: INVITE)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mapp_dial.ce[0m:e[1;37m3025e[0m e[1;37mdial_exec_fulle[0m: Exiting with DIALSTATUS=CANCEL.
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m342e[0m e[1;37m_ast_device_statee[0m: No provider found, checking channel drivers for SIP - cisco
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m5064e[0m e[1;37m__ast_pbx_rune[0m: Spawn extension (dso-cmd-startcall,s,7) exited non-zero on 'Local/s@dso-command-0000000a;2'
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mchan_sip.ce[0m:e[1;37m26634e[0m e[1;37msip_devicestatee[0m: Checking device state for peer cisco
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m2724e[0m e[1;37mast_softhangup_nolocke[0m: Soft-Hanging up channel 'Local/s@dso-command-0000000a;2'
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m460e[0m e[1;37mdo_state_changee[0m: Changing state for SIP/cisco - state 1 (Not in use)
[2013-05-30 17:17:56.826] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m440e[0m e[1;37mdevstate_evente[0m: device 'SIP/cisco' state '1'
[2013-05-30 17:17:56.827] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4143e[0m e[1;37mpbx_substitute_variables_helper_fulle[0m: Expression result is '1'
[2013-05-30 17:17:56.827] e[1;32mDEBUGe[0m[24538]: e[1;37mpbx.ce[0m:e[1;37m4247e[0m e[1;37mpbx_extension_helpere[0m: Launching 'ExecIf'
[2013-05-30 17:17:56.827] e[1;32mDEBUGe[0m[24538]: e[1;37mres_agi.ce[0m:e[1;37m3842e[0m e[1;37magi_exec_fulle[0m: Hungup channel detected, running agi in dead mode.

<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 200 canceling
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
To: <sip:00582743866@10.1.9.5>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-c1e6
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
CSeq: 102 CANCEL
Server: kamailio (3.3.0 (x86_64/linux))
Content-Length: 0

<------------->
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 21]: SIP/2.0 200 canceling
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 66]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 72]: To: <sip:00582743866@10.1.9.5>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-c1e6
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 16]: CSeq: 102 CANCEL
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 39]: Server: kamailio (3.3.0 (x86_64/linux))
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 17]: Content-Length: 0
--- (8 headers 0 lines) ---
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4045e[0m e[1;37m__sip_acke[0m: Acked pending invite 102
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4050e[0m e[1;37m__sip_acke[0m: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #202
[2013-05-30 17:17:56.830] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4083e[0m e[1;37m__sip_acke[0m: Stopping retransmission on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' of Request 102: Match Found

<--- SIP read from UDP:10.1.3.240:5060 --->
SIP/2.0 487 Request Cancelled
Reason: Q.850;cause=16
Date: Thu, 30 May 2013 15:22:37 GMT
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
Allow-Events: telephone-event
Content-Length: 0
To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
CSeq: 102 INVITE

e[KcvgVMasterisk1*CLI> 
e[0KServer: Cisco-SIPGateway/IOS-12.x

<------------->
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  0 [ 29]: SIP/2.0 487 Request Cancelled
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  1 [ 22]: Reason: Q.850;cause=16
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  2 [ 35]: Date: Thu, 30 May 2013 15:22:37 GMT
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  3 [ 61]: From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  4 [ 29]: Allow-Events: telephone-event
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  5 [ 17]: Content-Length: 0
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  6 [ 46]: To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  7 [ 57]: Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  8 [ 66]: Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport=5060
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header  9 [ 16]: CSeq: 102 INVITE
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m8587e[0m e[1;37mparse_requeste[0m:  Header 10 [ 33]: Server: Cisco-SIPGateway/IOS-12.x
--- (11 headers 0 lines) ---
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m4083e[0m e[1;37m__sip_acke[0m: Stopping retransmission on '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' of Request 102: Match Found
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m20169e[0m e[1;37mhandle_response_invitee[0m: SIP response 487 to standard invite
Transmitting (NAT) to 10.1.3.240:5060:
ACK sip:00582743866@10.1.9.5:5060 SIP/2.0
Via: SIP/2.0/UDP 10.1.3.233:5060;branch=z9hG4bK6ff41ce8;rport
Max-Forwards: 70
From: "0123456789" <sip:0123456789@10.1.3.233>;tag=as2ecb6e69
To: <sip:00582743866@10.1.9.5>;tag=DCBFED20-15
Contact: <sip:0123456789@10.1.3.233:5060>
Call-ID: 34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.8.17.0
Content-Length: 0


---
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m3399e[0m e[1;37m__sip_xmite[0m: Trying to put 'ACK sip:005' onto UDP socket destined for 10.1.3.240:5060
[2013-05-30 17:17:56.847] e[1;32mDEBUGe[0m[24136]: e[1;37mchan_sip.ce[0m:e[1;37m5971e[0m e[1;37mupdate_call_countere[0m: Updating call counter for outgoing call
Scheduling destruction of SIP dialog '34fdc2b7307eda36660efb293789ab6a@10.1.3.233:5060' in 12800 ms (Method: INVITE)

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24538]: e[1;37mchannel.ce[0m:e[1;37m2873e[0m e[1;37mast_hangupe[0m: Hanging up channel 'Local/s@dso-command-0000000a;2'

e[KcvgVMasterisk1*CLI> 
e[0K[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24540]: e[1;37mautochan.ce[0m:e[1;37m71e[0m e[1;37mast_autochan_destroye[0m: Removed autochan 0x1bc8d60 from the list, about to free it
[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m342e[0m e[1;37m_ast_device_statee[0m: No provider found, checking channel drivers for Local - s@dso-command
[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24124]: e[1;37mchan_local.ce[0m:e[1;37m302e[0m e[1;37mlocal_devicestatee[0m: Checking if extension s@dso-command exists (devicestate)
[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m460e[0m e[1;37mdo_state_changee[0m: Changing state for Local/s@dso-command - state 1 (Not in use)
[2013-05-30 17:17:57.244] e[1;32mDEBUGe[0m[24124]: e[1;37mdevicestate.ce[0m:e[1;37m440e[0m e[1;37mdevstate_evente[0m: device 'Local/s@dso-command' state '1'

e[KcvgVMasterisk1*CLI> exit
Asterisk ending (0).
e[0m

there are 2 files in the peers directory :

proxy.conf

[proxy]
type=peer
host=10.1.3.240

cisco.conf

[cisco]
type=peer
host=10.1.9.5

Don’t hesitate if you need something else.

4

The local channel, that you didn’t mention, is timing out on the Originate, that you didn’t mention!

Having verbose as well as debug output and having escape sequences stripped would have helped.

Why have you set up lots of templates, then not used them?

5

Yes ! You’re right, I use an http AMI that make an originate in a local channel. I redirect this channel to a context that make the Dial.

I have added the timeout parameter to my AMI request and it work fine.

Thanks you very much ! You saved my life (or just my Job :smiley: )

PS : I have to clean my Sip.conf to delete unused templates, you’re right again

Bye

Eric

6

I have same problem the call gets terminated after 30 seconds the dialstatus changed to cancel if the call nnot answered after 30 seconds

7

If you have the same problem, the solution will be the same.

8

What i’m actually running through is that

the call goes to for 30 rings after that i’m getting dialstatus=cancel instead of noanswer

exten => 1200,1,Dial(SIP/${EXTEN},40)
exten => 1200,2,Voicemail(${EXTEN}@default)
exten => 1200,3,hangup()

But after 40 second it’s not going to voicemail and i’m getting the message

Spawn extension exited non-zero on ‘SIP/1200-00000000’

9

If you are using Originate, it is the same problem and has the same solution.

If you are using Local channels, the Dial on the local channel timed out.

Otherwise the calling device timed out.

10

I’m not using originate a simple dialplan to make a call if destination not responding it should go to voicemail. This is what i’m trying to deploy in my setup but after 30 seconds it exited from the plan

11

As it is showing cancelled, that means that the calling peer ended the call. I’d suggest getting a SIP trace (sip set debug on) to confirm this. As timing is an issue, please enable the full log, and millisecond timestamps, in logger.conf and use the contents of hte full log, not a screen scrape.

I’d also suggest that you enable verbose level 5, so we can assure ourselves that this really is a simple call. The original poster on this thread failed to mention their use of originate.

If the source peer is terminating and you can’t address the problem at that end, you will need to explicitly answer the call in Asterisk. This will start any charging on anything upstream and stop that from taking effective action on no answer.

12

pleas find the logss

13

Both to and from addresses seem to be the same; you need to correct that.

Assuming that is a case of overzealous redaction, when presenting redacted addresses it is important that different addresses appear different and that routeable addreses have routable address prefixes and non-routable ones have non-routable prefixes.

The caller did abandon the call, and, especially given that they are not returning OPTIONS responses, I think you have a problem that traffic routed to xxx.xxx.xxx.xxx is not arriving there, or xxx.xxx.xxx.xxx is the wrong address.