183 session progress

roshan25 · July 20, 2013, 4:09pm

Hello Everyone…

Thanks for reading this.

I am new to asterisk. I am trying to make outbound call from asterisk. Currently, I can send INVITE with SDP, receive TRYING and 183 SESSION PROGRESS. But after sometime, I receive “404 NOT FOUND”. The provider says that their device expects reply to 183 SESSION PROGRESS.

I tried asterisk 1.6 and 1.8 but I am unable to figure out why asterisk is not replying/acknowledging the 183 session progress.

Do we really need to send response/acknowledge 183 session progress? Please help.

My SIP.CONF is as follows

SIP.CONF

[general]

directrtpsetup=yes
registertimeout=20
context=test
bindport=5060
bindaddr=0.0.0.0
localnet=10.0.0.0/255.255.255.0
externip = 192.168.81.200
srvlookup=no
allow= g723
dtmfmode=info
progressinband=yes
nat=yes
canreinvite=yes
[VoIPProvider]
context=test
type=peer
qualify=yes
fromuser=3650
username=3650
host=116.68.210.20
dtmfmode=info
disallow=all
allow=g723

LOGS

centos5VMCLI> [Jul 20 21:05:32] DEBUG[4196]: manager.c:4795 process_message: Running action ‘Originate’
[Jul 20 21:05:32] DEBUG[4196]: manager.c:4795 process_message: Running action 'Originate’
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:27297 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8227 sip_alloc: Allocating new SIP dialog for 4697c3ae04db7f330ab99b18277c41cf@127.0.0.1:5060 - INVITE (No RTP)
[Jul 20 21:05:32] DEBUG[4197]: rtp_engine.c:350 ast_rtp_instance_new: Using engine ‘asterisk’ for RTP instance ‘0x10df92b8’
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:27297 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8227 sip_alloc: Allocating new SIP dialog for 4697c3ae04db7f330ab99b18277c41cf@127.0.0.1:5060 - INVITE (No RTP)
[Jul 20 21:05:32] DEBUG[4197]: rtp_engine.c:350 ast_rtp_instance_new: Using engine ‘asterisk’ for RTP instance '0x10df92b8’
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 43040 for RTP instance ‘0x10df92b8’
[Jul 20 21:05:32] DEBUG[4197]: res_rtp_asterisk.c:558 ast_rtp_new: Allocated port 43040 for RTP instance '0x10df92b8’
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance ‘0x10df92b8’ is setup and ready to go
[Jul 20 21:05:32] DEBUG[4197]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance ‘0x10df92b8’ is setup and ready to go
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: res_rtp_asterisk.c:2543 ast_rtp_prop_set: Setup RTCP on RTP instance ‘0x10df92b8’
[Jul 20 21:05:32] DEBUG[4197]: res_rtp_asterisk.c:2543 ast_rtp_prop_set: Setup RTCP on RTP instance '0x10df92b8’
centos5VMCLI> == Using SIP RTP CoS mark 5
== Using SIP RTP CoS mark 5
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:5474 do_setnat: Setting NAT on RTP to On
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:5474 do_setnat: Setting NAT on RTP to On
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3487 obproxy_get: OBPROXY: Not applying OBproxy to this call
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3487 obproxy_get: OBPROXY: Not applying OBproxy to this call
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: acl.c:736 ast_ouraddrfor: For destination ‘116.68.210.20’, our source address is ‘10.0.0.2’.
[Jul 20 21:05:32] DEBUG[4197]: acl.c:736 ast_ouraddrfor: For destination ‘116.68.210.20’, our source address is ‘10.0.0.2’.
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3806 ast_sip_ouraddrfor: Target address 116.68.210.20:5060 is not local, substituting externaddr
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3806 ast_sip_ouraddrfor: Target address 116.68.210.20:5060 is not local, substituting externaddr
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3839 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3839 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8053 change_callid_pvt: SIP call-id changed from ‘4697c3ae04db7f330ab99b18277c41cf@127.0.0.1:5060’ to ‘06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060’
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8053 change_callid_pvt: SIP call-id changed from ‘4697c3ae04db7f330ab99b18277c41cf@127.0.0.1:5060’ to '06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060’
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7515 sip_new: *** Our native formats are 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7515 sip_new: *** Our native formats are 0x1 (g723)
centos5VMCLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7516 sip_new: *** Joint capabilities are 0x0 (nothing)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7516 sip_new: *** Joint capabilities are 0x0 (nothing)
centos5VM*CLI> [Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7517 sip_new: *** Our capabilities are 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7518 sip_new: *** AST_CODEC_CHOOSE formats are 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7520 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7548 sip_new: This channel will not be able to handle video.
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:6017 sip_call: Outgoing Call for 9801018432
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:6300 update_call_counter: Updating call counter for outgoing call
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11884 add_sdp: ** Our capability: 0x1 (g723) Video flag: False Text flag: False
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11885 add_sdp: ** Our prefcodec: 0x40 (slin)
Audio is at 43040
Adding codec 0x1 (g723) to SDP
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11994 add_sdp: – Done with adding codecs to SDP
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:12180 add_sdp: Done building SDP. Settling with this capability: 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3363 initialize_initreq: Initializing initreq for method INVITE - callid 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 0 [ 43]: INVITE sip:9801018432@116.68.210.20 SIP/2.0
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK408a9c96;rport
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 3 [ 59]: From: “9801018432” sip:3650@192.168.81.200;tag=as706b7b80
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 4 [ 34]: To: sip:9801018432@116.68.210.20
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 5 [ 39]: Contact: sip:3650@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 6 [ 61]: Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 7 [ 16]: CSeq: 102 INVITE
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.23.0
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 9 [ 35]: Date: Sat, 20 Jul 2013 15:20:32 GMT
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 11 [ 26]: Supported: replaces, timer
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 12 [ 29]: Content-Type: application/sdp
Reliably Transmitting (NAT) to 116.68.210.20:5060:
INVITE sip:9801018432@116.68.210.20 SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK408a9c96;rport
Max-Forwards: 70
From: “9801018432” sip:3650@192.168.81.200;tag=as706b7b80
To: sip:9801018432@116.68.210.20
Contact: sip:3650@192.168.81.200:5060
Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.23.0
Date: Sat, 20 Jul 2013 15:20:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 232

v=0
o=root 1328787650 1328787650 IN IP4 192.168.81.200
s=Asterisk PBX 1.8.23.0
c=IN IP4 192.168.81.200
t=0 0
m=audio 43040 RTP/AVP 4
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:4142 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #59
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3687 __sip_xmit: Trying to put ‘INVITE sip:’ onto UDP socket destined for 116.68.210.20:5060
[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context: test
Uniqueid: 1374333632.0

[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: NewAccountCode
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
Uniqueid: 1374333632.0
AccountCode: test
OldAccountCode:

[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
CallerIDNum: 3650
CallerIDName: 9801018432
Uniqueid: 1374333632.0
CID-CallingPres: 0 (Presentation Allowed, Not Screened)

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 100 Trying
Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
Server: CISCO-SBC/2.x
Content-Length: 0

<------------->
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 1 [ 61]: Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 7 [ 17]: Content-Length: 0
— (8 headers 0 lines) —
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8547 find_call: = Looking for Call ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060 (Checking To) --From tag as706b7b80 --To-tag sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7517 sip_new: *** Our capabilities are 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7518 sip_new: *** AST_CODEC_CHOOSE formats are 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7520 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:7548 sip_new: This channel will not be able to handle video.
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:6017 sip_call: Outgoing Call for 9801018432
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:6300 update_call_counter: Updating call counter for outgoing call
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11884 add_sdp: ** Our capability: 0x1 (g723) Video flag: False Text flag: False
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11885 add_sdp: ** Our prefcodec: 0x40 (slin)
Audio is at 43040
Adding codec 0x1 (g723) to SDP
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:11994 add_sdp: – Done with adding codecs to SDP
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:12180 add_sdp: Done building SDP. Settling with this capability: 0x1 (g723)
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3363 initialize_initreq: Initializing initreq for method INVITE - callid 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 0 [ 43]: INVITE sip:9801018432@116.68.210.20 SIP/2.0
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK408a9c96;rport
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 3 [ 59]: From: “9801018432” sip:3650@192.168.81.200;tag=as706b7b80
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 4 [ 34]: To: sip:9801018432@116.68.210.20
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 5 [ 39]: Contact: sip:3650@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 6 [ 61]: Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 7 [ 16]: CSeq: 102 INVITE
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.23.0
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 9 [ 35]: Date: Sat, 20 Jul 2013 15:20:32 GMT
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 11 [ 26]: Supported: replaces, timer
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:8956 parse_request: Header 12 [ 29]: Content-Type: application/sdp
Reliably Transmitting (NAT) to 116.68.210.20:5060:
INVITE sip:9801018432@116.68.210.20 SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK408a9c96;rport
Max-Forwards: 70
From: “9801018432” sip:3650@192.168.81.200;tag=as706b7b80
To: sip:9801018432@116.68.210.20
Contact: sip:3650@192.168.81.200:5060
Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.23.0
Date: Sat, 20 Jul 2013 15:20:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 232

v=0
o=root 1328787650 1328787650 IN IP4 192.168.81.200
s=Asterisk PBX 1.8.23.0
c=IN IP4 192.168.81.200
t=0 0
m=audio 43040 RTP/AVP 4
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:4142 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #59
[Jul 20 21:05:32] DEBUG[4197]: chan_sip.c:3687 __sip_xmit: Trying to put ‘INVITE sip:’ onto UDP socket destined for 116.68.210.20:5060
[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context: test
Uniqueid: 1374333632.0

[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: NewAccountCode
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
Uniqueid: 1374333632.0
AccountCode: test
OldAccountCode:

[Jul 20 21:05:32] DEBUG[4196]: manager.c:4376 match_filter: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/VoIPProvider-00000000
CallerIDNum: 3650
CallerIDName: 9801018432
Uniqueid: 1374333632.0
CID-CallingPres: 0 (Presentation Allowed, Not Screened)

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 100 Trying
Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
Server: CISCO-SBC/2.x
Content-Length: 0

<------------->
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 1 [ 61]: Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 7 [ 17]: Content-Length: 0
— (8 headers 0 lines) —
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8547 find_call: = Looking for Call ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060 (Checking To) --From tag as706b7b80 --To-tag sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:4405 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #59 - INVITE (got response)
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:4412 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060’ Request 102: Found
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:20713 handle_response_invite: SIP response 100 to standard invite
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:4405 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #59 - INVITE (got response)
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:4412 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060’ Request 102: Found
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:20713 handle_response_invite: SIP response 100 to standard invite
centos5VM*CLI>
<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 183 Session Progress
Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
Server: CISCO-SBC/2.x
Content-Length: 188
Contact: sip:116.68.210.20:5060
Content-Type: application/sdp

v=0
o=- 82463671242304 82463671242304 IN IP4 116.68.210.21
s=-
c=IN IP4 116.68.210.21
t=0 0
m=audio 16496 RTP/AVP 4
a=sendrecv
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=ptime:30
<------------->
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 0 [ 28]: SIP/2.0 183 Session Progress
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 1 [ 61]: Call-ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as706b7b80
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK408a9c96
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 7 [ 19]: Content-Length: 188
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Header 10 [ 0]:
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 0 [ 3]: v=0
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 1 [ 54]: o=- 82463671242304 82463671242304 IN IP4 116.68.210.21
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 2 [ 3]: s=-
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 4 [ 5]: t=0 0
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 5 [ 23]: m=audio 16496 RTP/AVP 4
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 7 [ 20]: a=rtpmap:4 G723/8000
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8956 parse_request: Body 8 [ 18]: a=fmtp:4 annexa=no
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8993 parse_request: Body 9 [ 10]: a=ptime:30
— (10 headers 10 lines) —
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:8547 find_call: = Looking for Call ID: 06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060 (Checking To) --From tag as706b7b80 --To-tag sip+1+1b490003+49141f0b
[Jul 20 21:05:32] DEBUG[4160]: chan_sip.c:4412 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘06f74892773e8dc94028c5392f6be5cc@192.168.81.200:5060’ Request 102: Found

david55 · July 20, 2013, 7:02pm

Acknowledging a non-final response is optional. I don’t know if Asterisk 1.8 supports that. 1.6 doesn’t. There is a special sort of acknowledgment.

I don’t see anything requesting intermediate acknowledgements and 404 does not seem an appropriate response if they are lacking.

david55 · July 20, 2013, 7:06pm

The defining document is RFC 3262. The Cisco has no right to expect such responses because Asterisk did not send Supports: 100rel.

[quote]3 UAS Behavior

A UAS MAY send any non-100 provisional response to INVITE reliably,
so long as the initial INVITE request (the request whose provisional
response is being sent reliably) contained a Supported header field
with the option tag 100rel. While this specification does not allow
reliable provisional responses for any method but INVITE, extensions
that define new methods that can establish dialogs may make use of
the mechanism.
[/quote]

roshan25 · July 22, 2013, 11:27am

Hi David,

Thank you for your reply. Your reply was VERY helpful. Now the provider has taken care of the issue at their end.

Now my outgoing call is successful but I am unable to hear any audio. I am using G729a codec. Could you please see my log and check if there is any issue or any misconfiguration in my sip.conf?

<------------->
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 38]: OPTIONS sip:110.44.126.36:3062 SIP/2.0
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+93d33dcbadf8ca87246b9c8e220f08031+sip+1+a918b432
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 38]: Call-ID: F9D1EE32-1@116.68.210.20:5060
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 60]: From: sip:116.68.210.20:5060;lr;tag=sip+1+d730010+83840a5a
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 23]: CSeq: 216650735 OPTIONS
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 17]: Content-Length: 0
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 26]: To: sip:110.44.126.36:3062
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 36]: Contact: sip:116.68.210.20:5060;lr
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 47]: Accept: application/sdp, application/dtmf-relay
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
— (10 headers 0 lines) —
[Jul 22 15:02:04] DEBUG[3883]: acl.c:507 ast_ouraddrfor: Found IP address for this socket
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:3824 ast_sip_ouraddrfor: Target address 116.68.210.20 is not local, substituting externip
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:3852 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:7527 sip_alloc: Allocating new SIP dialog for F9D1EE32-1@116.68.210.20:5060 - OPTIONS (No RTP)
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:22078 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS
Looking for s in test (domain 110.44.126.36)

<— Transmitting (NAT) to 116.68.210.20:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+93d33dcbadf8ca87246b9c8e220f08031+sip+1+a918b432;received=116.68.210.20
From: sip:116.68.210.20:5060;lr;tag=sip+1+d730010+83840a5a
To: sip:110.44.126.36:3062;tag=as1a0153c2
Call-ID: F9D1EE32-1@116.68.210.20:5060
CSeq: 216650735 OPTIONS
Server: Asterisk PBX 1.6.2.17.3
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: sip:192.168.81.200
Accept: application/sdp
Content-Length: 0

<------------>
[Jul 22 15:02:04] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘SIP/2.0 200’ onto UDP socket destined for 116.68.210.20:5060
Scheduling destruction of SIP dialog ‘F9D1EE32-1@116.68.210.20:5060’ in 32000 ms (Method: OPTIONS)
test4SIP*CLI> [Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 28]: SIP/2.0 183 Session Progress
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:4321 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ Request 102: Found
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 183 to standard invite
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP o=- 128948253125122 128948253125122 IN IP4 116.68.210.21… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP s=-… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP c=IN IP4 116.68.210.21… OK.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP t=0 0… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=sendrecv… OK.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000… OK.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=ptime:20… OK.

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 183 Session Progress
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
Server: CISCO-SBC/2.x
Content-Length: 193
Contact: sip:116.68.210.20:5060
Content-Type: application/sdp

v=0
o=- 128948253125122[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8833 process_sdp: We’re settling with these formats: 0x100 (g729)
128948253125122 IN IP4 116.68.210.21
s=-
c=IN IP4 116.68.210.21
t=0 0
m=audio 16546 RTP/AVP 18
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20

<------------->
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 28]: SIP/2.0 183 Session Progress
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.16[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8838 process_sdp: We have an owner, now see if we need to change this call
8.81.200
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
— (10 headers 10 lines) —
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:4321 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ Request 102: Found
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 183 to standard invite
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP o=- 128948253125122 128948253125122 IN IP4 116.68.210.21… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP s=-… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP c=IN IP4 116.68.210.21… OK.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP t=0 0… UNSUPPORTED.
Found RTP audio format 18
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=sendrecv… OK.
Found audio description format G729 for ID 18
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000… OK.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no… UNSUPPORTED.
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8629 process_sdp: Processing media-level (audio) SDP a=ptime:20… OK.
Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x100 (g729)
Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing)
Peer audio RTP is at port 116.68.210.21:16546
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8833 process_sdp: We’re settling with these formats: 0x100 (g729)
[Jul 22 15:02:05] DEBUG[3883]: chan_sip.c:8838 process_sdp: We have an owner, now see if we need to change this call
test4SIP*CLI> [Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:4321 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ Request 102: Found
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 180 to standard invite
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8948 process_sdp_o: Call 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200 responded to our reinvite without changing SDP version; ignoring SDP.

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 180 Ringing
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
Server: CISCO-SBC/2.x
Content-Length: 193
Contact: sip:116.68.210.20:5060
Content-Type: application/sdp

v=0
o=- 128948253125122 12894825[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
[Jul 22 15:02:06] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
3125122 IN IP4 116.68.210.21
s=-
c=IN IP4 116.68.210.21
t=0 0
m=audio 16546 RTP/AVP 18
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20

<------------->
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 1[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
5:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
— (10 headers 10 lines) —
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:4321 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining pack[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state '1’
et) on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ Request 102: Found
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 180 to standard invite
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:06] DEBUG[3883]: chan_sip.c:8948 process_sdp_o: Call 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200 responded to our reinvite without changing SDP version; ignoring SDP.
[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
[Jul 22 15:02:06] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
[Jul 22 15:02:06] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state '1’
test4SIP*CLI> [Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:4243 __sip_ack: Acked pending invite 102
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ of Request 102: Match Found
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 200 to standard invite
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8948 process_sdp_o: Call 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200 responded to our reinvite without changing SDP version; ignoring SDP.
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:5842 update_call_counter: Updating call counter for outgoing call
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:12842 build_route: build_route: Contact hop: sip:116.68.210.20:5060
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:9775 reqprep: Strict routing enforced for session 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘ACK sip:116’ onto UDP socket destined for 116.68.210.20:5060

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 200 OK
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 102 INVITE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
Server: CISCO-SBC/2.x
Content-Length: 193
Contact: sip:116.68.210.20:5060
Content-Type: application/sdp

v=0
o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
s=-
c=IN IP4 116.68.210.21
t=0 0
m=audio 16546 RTP/AVP 18
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20

<------------->
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: CSeq: 102 INVITE
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK4ba19706
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 19]: Content-Length: 193
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 29]: Content-Type: application/sdp
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 0 [ 3]: v=0
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 1 [ 56]: o=- 128948253125122 128948253125122 IN IP4 116.68.210.21
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 2 [ 3]: s=-
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 3 [ 22]: c=IN IP4 116.68.210.21
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 4 [ 5]: t=0 0
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 5 [ 24]: m=audio 16546 RTP/AVP 18
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 6 [ 10]: a=sendrecv
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8053 parse_request: Body 9 [ 10]: a=ptime:20
— (10 headers 10 lines) —
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:4243 __sip_ack: Acked pending invite 102
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ of Request 102: Match Found
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:17962 handle_response_invite: SIP response 200 to standard invite
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8461 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:8948 process_sdp_o: Call 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200 responded to our reinvite without changing SDP version; ignoring SDP.
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:5842 update_call_counter: Updating call counter for outgoing call
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:12842 build_route: build_route: Contact hop: sip:116.68.210.20:5060
list_route: hop: sip:116.68.210.20:5060
[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:9775 reqprep: Strict routing enforced for session 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
set_destination: Parsing sip:116.68.210.20:5060 for address/port to send to
set_destination: set destination to 116.68.210.20, port 5060
Transmitting (NAT) to 116.68.210.20:5060:
ACK sip:116.68.210.20:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK0ec95584;rport
[Jul 22 15:02:27] DEBUG[3899]: pbx.c:3708 pbx_extension_helper: Launching ‘AGI’

From: “9801018432” sip:3650@192.168.81.200;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Contact: sip:3650@192.168.81.200
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.6.2.17.3
Content-Length: 0

[Jul 22 15:02:27] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘ACK sip:116’ onto UDP socket destined for 116.68.210.20:5060
> Channel SIP/VoIPProvider-00000000 was answered.
[Jul 22 15:02:27] DEBUG[3899]: pbx.c:3708 pbx_extension_helper: Launching ‘AGI’
– Executing [s@test:1] AGI(“SIP/VoIPProvider-00000000”, “agi://10.0.0.17:4573/customivr?sender-9851055168;usecaseID-1;amount-201;pin-1234;txnid-1234567890;lang-en;receiver-9851055168;”) in new stack
test4SIPCLI> [Jul 22 15:02:27] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
[Jul 22 15:02:27] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
test4SIPCLI> [Jul 22 15:02:27] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
[Jul 22 15:02:27] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
test4SIPCLI> [Jul 22 15:02:27] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
[Jul 22 15:02:27] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
[Jul 22 15:02:27] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state ‘1’
[Jul 22 15:02:27] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state '1’
test4SIPCLI> [Jul 22 15:02:27] DEBUG[3899]: res_agi.c:861 launch_netscript: Wow, connected!
[Jul 22 15:02:27] DEBUG[3899]: res_agi.c:861 launch_netscript: Wow, connected!
– Playing ‘/cello/apps/asterisk/current/var/lib/asterisk/sounds/en/that-is-not-rec-phn-num’ (escape_digits=0123456789*#) (sample_offset 0)
test4SIP*CLI> [Jul 22 15:02:28] DEBUG[3899]: rtp.c:3890 ast_rtp_write: Ooh, format changed from unknown to g729
[Jul 22 15:02:28] DEBUG[3899]: rtp.c:3916 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20
[Jul 22 15:02:28] DEBUG[3899]: rtp.c:3890 ast_rtp_write: Ooh, format changed from unknown to g729
[Jul 22 15:02:28] DEBUG[3899]: rtp.c:3916 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20

test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: channel.c:1750 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/VoIPProvider-00000000’
[Jul 22 15:02:36] DEBUG[3899]: res_agi.c:2903 run_agi: SIP/VoIPProvider-00000000 hungup
[Jul 22 15:02:36] DEBUG[3899]: channel.c:1750 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/VoIPProvider-00000000’
[Jul 22 15:02:36] DEBUG[3899]: res_agi.c:2903 run_agi: SIP/VoIPProvider-00000000 hungup
– <SIP/VoIPProvider-00000000>AGI Script agi://10.0.0.17:4573/customivr?sender-9 … 851055168; completed, returning -1
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: pbx.c:4335 __ast_pbx_run: Extension s, priority 1 returned normally even though call was hung up
[Jul 22 15:02:36] DEBUG[3899]: pbx.c:4335 __ast_pbx_run: Extension s, priority 1 returned normally even though call was hung up
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: channel.c:1750 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/VoIPProvider-00000000’
[Jul 22 15:02:36] DEBUG[3899]: channel.c:1750 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/VoIPProvider-00000000’
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: channel.c:1855 ast_hangup: Hanging up channel ‘SIP/VoIPProvider-00000000’
[Jul 22 15:02:36] DEBUG[3899]: channel.c:1855 ast_hangup: Hanging up channel 'SIP/VoIPProvider-00000000’
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:6207 sip_hangup: Hangup call SIP/VoIPProvider-00000000, SIP callid 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:6207 sip_hangup: Hangup call SIP/VoIPProvider-00000000, SIP callid 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
Scheduling destruction of SIP dialog ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ in 6400 ms (Method: INVITE)
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:9775 reqprep: Strict routing enforced for session 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:9775 reqprep: Strict routing enforced for session 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
set_destination: Parsing sip:116.68.210.20:5060 for address/port to send to
set_destination: set destination to 116.68.210.20, port 5060
Reliably Transmitting (NAT) to 116.68.210.20:5060:
BYE sip:116.68.210.20:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK72922565;rport
Max-Forwards: 70
From: “9801018432” sip:3650@192.168.81.200;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 103 BYE
User-Agent: Asterisk PBX 1.6.2.17.3
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:4084 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #10
[Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:4084 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #10
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:3731 __sip_xmit: Trying to put ‘BYE sip:116’ onto UDP socket destined for 116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3899]: chan_sip.c:3731 __sip_xmit: Trying to put ‘BYE sip:116’ onto UDP socket destined for 116.68.210.20:5060
test4SIP*CLI> [Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 13]: CSeq: 103 BYE
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK72922565
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 0]:
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4248 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ of Request 103: Match Found
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 200 OK
Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
CSeq: 103 BYE
From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK72922565
Server: CISCO-SBC/2.x
Content-Length: 0
Contact: sip:116.68.210.20:5060

<------------->
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 56]: Call-ID: 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 13]: CSeq: 103 BYE
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 64]: From: “9801018432” sip:3650@192.168.81.200:5060;tag=as643c43c2
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 62]: To: sip:9801018432@116.68.210.20;tag=sip+1+16ff0010+8d77420b
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK72922565
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 33]: Contact: sip:116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 0]:
— (9 headers 0 lines) —
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4248 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ of Request 103: Match Found
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog 3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200
Really destroying SIP dialog ‘3aee9bc93c0450aa4fd253f7120df0ee@192.168.81.200’ Method: INVITE
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
[Jul 22 15:02:36] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
[Jul 22 15:02:36] DEBUG[3873]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - VoIPProvider
[Jul 22 15:02:36] DEBUG[3873]: chan_sip.c:23445 sip_devicestate: Checking device state for peer VoIPProvider
[Jul 22 15:02:36] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
[Jul 22 15:02:36] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state ‘1’
[Jul 22 15:02:36] DEBUG[3873]: devicestate.c:462 do_state_change: Changing state for SIP/VoIPProvider - state 1 (Not in use)
[Jul 22 15:02:36] DEBUG[3873]: devicestate.c:442 devstate_event: device ‘SIP/VoIPProvider’ state '1’
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 38]: OPTIONS sip:110.44.126.36:3062 SIP/2.0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+14a832beea3ee284fefec64fc91d81b31+sip+1+a918b4cc
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 38]: Call-ID: 8374A6AB-1@116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 60]: From: sip:116.68.210.20:5060;lr;tag=sip+1+ae00011+61ef15fa
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 24]: CSeq: 1006285107 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 26]: To: sip:110.44.126.36:3062
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 36]: Contact: sip:116.68.210.20:5060;lr
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 47]: Accept: application/sdp, application/dtmf-relay
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
[Jul 22 15:02:36] DEBUG[3883]: acl.c:507 ast_ouraddrfor: Found IP address for this socket
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3824 ast_sip_ouraddrfor: Target address 116.68.210.20 is not local, substituting externip
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3852 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:7527 sip_alloc: Allocating new SIP dialog for 8374A6AB-1@116.68.210.20:5060 - OPTIONS (No RTP)
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:22078 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘SIP/2.0 200’ onto UDP socket destined for 116.68.210.20:5060

<— SIP read from UDP:116.68.210.20:5060 —>
OPTIONS sip:110.44.126.36:3062 SIP/2.0
Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+14a832beea3ee284fefec64fc91d81b31+sip+1+a918b4cc
Max-Forwards: 70
Call-ID: 8374A6AB-1@116.68.210.20:5060
From: sip:116.68.210.20:5060;lr;tag=sip+1+ae00011+61ef15fa
CSeq: 1006285107 OPTIONS
Content-Length: 0
To: sip:110.44.126.36:3062
Contact: sip:116.68.210.20:5060;lr
Accept: application/sdp, application/dtmf-relay

<------------->
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 38]: OPTIONS sip:110.44.126.36:3062 SIP/2.0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+14a832beea3ee284fefec64fc91d81b31+sip+1+a918b4cc
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 38]: Call-ID: 8374A6AB-1@116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 60]: From: sip:116.68.210.20:5060;lr;tag=sip+1+ae00011+61ef15fa
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 24]: CSeq: 1006285107 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 26]: To: sip:110.44.126.36:3062
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 36]: Contact: sip:116.68.210.20:5060;lr
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 47]: Accept: application/sdp, application/dtmf-relay
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 0]:
— (10 headers 0 lines) —
[Jul 22 15:02:36] DEBUG[3883]: acl.c:507 ast_ouraddrfor: Found IP address for this socket
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3824 ast_sip_ouraddrfor: Target address 116.68.210.20 is not local, substituting externip
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3852 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:7527 sip_alloc: Allocating new SIP dialog for 8374A6AB-1@116.68.210.20:5060 - OPTIONS (No RTP)
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:22078 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS
Looking for s in test (domain 110.44.126.36)

<— Transmitting (NAT) to 116.68.210.20:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 116.68.210.20:5060;branch=z9hG4bK+14a832beea3ee284fefec64fc91d81b31+sip+1+a918b4cc;received=116.68.210.20
From: sip:116.68.210.20:5060;lr;tag=sip+1+ae00011+61ef15fa
To: sip:110.44.126.36:3062;tag=as2295b13f
Call-ID: 8374A6AB-1@116.68.210.20:5060
CSeq: 1006285107 OPTIONS
Server: Asterisk PBX 1.6.2.17.3
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: sip:192.168.81.200
Accept: application/sdp
Content-Length: 0

<------------>
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘SIP/2.0 200’ onto UDP socket destined for 116.68.210.20:5060
Scheduling destruction of SIP dialog ‘8374A6AB-1@116.68.210.20:5060’ in 32000 ms (Method: OPTIONS)
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4163 __sip_autodestruct: Auto destroying SIP dialog ‘F9D1EE32-1@116.68.210.20:5060’
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog F9D1EE32-1@116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4163 __sip_autodestruct: Auto destroying SIP dialog ‘F9D1EE32-1@116.68.210.20:5060’
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog F9D1EE32-1@116.68.210.20:5060
Really destroying SIP dialog ‘F9D1EE32-1@116.68.210.20:5060’ Method: OPTIONS
test4SIPCLI> [Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:7527 sip_alloc: Allocating new SIP dialog for 73231c8848702bc221769ffb7b392048@10.0.0.2 - OPTIONS (No RTP)
[Jul 22 15:02:36] DEBUG[3883]: acl.c:507 ast_ouraddrfor: Found IP address for this socket
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3824 ast_sip_ouraddrfor: Target address 116.68.210.20 is not local, substituting externip
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3852 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3417 initialize_initreq: Initializing initreq for method OPTIONS - callid 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 33]: OPTIONS sip:116.68.210.20 SIP/2.0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK37afaeb8;rport
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 61]: From: “asterisk” sip:asterisk@192.168.81.200;tag=as542c43da
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 23]: To: sip:116.68.210.20
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 38]: Contact: sip:asterisk@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 56]: Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 35]: User-Agent: Asterisk PBX 1.6.2.17.3
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 35]: Date: Mon, 22 Jul 2013 09:17:36 GMT
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 11 [ 26]: Supported: replaces, timer
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4084 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #12
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 116.68.210.20:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:7527 sip_alloc: Allocating new SIP dialog for 73231c8848702bc221769ffb7b392048@10.0.0.2 - OPTIONS (No RTP)
[Jul 22 15:02:36] DEBUG[3883]: acl.c:507 ast_ouraddrfor: Found IP address for this socket
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3824 ast_sip_ouraddrfor: Target address 116.68.210.20 is not local, substituting externip
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3852 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3417 initialize_initreq: Initializing initreq for method OPTIONS - callid 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 33]: OPTIONS sip:116.68.210.20 SIP/2.0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK37afaeb8;rport
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 61]: From: “asterisk” sip:asterisk@192.168.81.200;tag=as542c43da
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 23]: To: sip:116.68.210.20
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 38]: Contact: sip:asterisk@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 56]: Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 35]: User-Agent: Asterisk PBX 1.6.2.17.3
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 35]: Date: Mon, 22 Jul 2013 09:17:36 GMT
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 11 [ 26]: Supported: replaces, timer
Reliably Transmitting (NAT) to 116.68.210.20:5060:
OPTIONS sip:116.68.210.20 SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK37afaeb8;rport
Max-Forwards: 70
From: “asterisk” sip:asterisk@192.168.81.200;tag=as542c43da
To: sip:116.68.210.20
Contact: sip:asterisk@192.168.81.200
Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.6.2.17.3
Date: Mon, 22 Jul 2013 09:17:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4084 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #12
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:3731 __sip_xmit: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 116.68.210.20:5060
test4SIP*CLI> [Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 66]: From: “asterisk” sip:asterisk@192.168.81.200:5060;tag=as542c43da
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 51]: To: sip:116.68.210.20;tag=sip+1+10ee0011+3d452627
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK37afaeb8
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 43]: Contact: sip:asterisk@192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 56]: Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 17]: CSeq: 102 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 35]: User-Agent: Asterisk PBX 1.6.2.17.3
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 35]: Date: Mon, 22 Jul 2013 09:17:36 GMT
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 12 [ 26]: Supported: replaces, timer
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 13 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 14 [ 0]:
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4248 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘13e7011d10db6d98184dc2b502af89d1@192.168.81.200’ of Request 102: Match Found
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog 13e7011d10db6d98184dc2b502af89d1@192.168.81.200

<— SIP read from UDP:116.68.210.20:5060 —>
SIP/2.0 200 OK
From: “asterisk” sip:asterisk@192.168.81.200:5060;tag=as542c43da
To: sip:116.68.210.20;tag=sip+1+10ee0011+3d452627
Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK37afaeb8
Server: CISCO-SBC/2.x
Max-Forwards: 70
Contact: sip:asterisk@192.168.81.200:5060
Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.6.2.17.3
Date: Mon, 22 Jul 2013 09:17:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

<------------->
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 0 [ 14]: SIP/2.0 200 OK
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 1 [ 66]: From: “asterisk” sip:asterisk@192.168.81.200:5060;tag=as542c43da
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 2 [ 51]: To: sip:116.68.210.20;tag=sip+1+10ee0011+3d452627
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 3 [ 88]: Via: SIP/2.0/UDP 192.168.81.200:5060;received=10.0.0.2;rport=5060;branch=z9hG4bK37afaeb8
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 4 [ 21]: Server: CISCO-SBC/2.x
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 5 [ 16]: Max-Forwards: 70
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 6 [ 43]: Contact: sip:asterisk@192.168.81.200:5060
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 7 [ 56]: Call-ID: 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 8 [ 17]: CSeq: 102 OPTIONS
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 9 [ 35]: User-Agent: Asterisk PBX 1.6.2.17.3
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 10 [ 35]: Date: Mon, 22 Jul 2013 09:17:36 GMT
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 12 [ 26]: Supported: replaces, timer
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 13 [ 17]: Content-Length: 0
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:8053 parse_request: Header 14 [ 0]:
— (14 headers 0 lines) —
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4248 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:4280 __sip_ack: Stopping retransmission on ‘13e7011d10db6d98184dc2b502af89d1@192.168.81.200’ of Request 102: Match Found
[Jul 22 15:02:36] DEBUG[3883]: chan_sip.c:5989 sip_destroy: Destroying SIP dialog 13e7011d10db6d98184dc2b502af89d1@192.168.81.200
Really destroying SIP dialog ‘13e7011d10db6d98184dc2b502af89d1@192.168.81.200’ Method: OPTIONS

Thank you so much for your help.

regards,
Roshan

david55 · July 22, 2013, 12:27pm

The trace shows a re-invite, but not the original invite.

Topic		Replies	Views
183 session progress Asterisk Support	0	161	October 3, 2006
183 Session Progress Asterisk General	2	1078	May 3, 2012
SIP 183, session progress Asterisk Support	0	235	January 25, 2006
Not Sending response to the 200 OK IP Asterisk SIP	4	1404	May 23, 2019
How to disable 183 Session Progress Asterisk SIP	5	1698	May 5, 2022

183 session progress

SIP.CONF

LOGS

Related topics