99% of the time 30 seconds hangup (or 32seconds) means a NAT problem... or a response not come back to source... 2016-04-08 17:06 GMT+02:00 Jurijs Ivolga <jurijs.ivolga@gmail.com>:
Hi,
This is not what I need, please use ngrep:
http://jonathanmanning.com/2009/11/17/how-to-sip-capture-using-ngrep-debug-s...
With kind regards,
Jurijs
On Fri, Apr 8, 2016 at 6:02 PM, Стас Тельнов <stasan89@gmail.com> wrote:
Yes, of cause. I hide some ip and real phone numbers. 178.*.*.12 - ip of provider.
*On start call:* 2016-04-08 10:47:10.503262 [NOTICE] switch_channel.c:1101 New Channel sofia/external/8@sip0.MY_DOMAIN.com [c618eafe-fd98-11e5-a353-831849fc41a3] 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_NEW 2016-04-08 10:47:10.503262 [DEBUG] sofia.c:9248 sofia/external/ 8@sip0.MY_DOMAIN.com receiving invite from 172.31.0.169:5060 version: 1.6.6 64bit 2016-04-08 10:47:10.503262 [DEBUG] sofia.c:6760 Channel sofia/external/ 8@sip0.MY_DOMAIN.com entering state [received][100] 2016-04-08 10:47:10.503262 [DEBUG] sofia.c:6770 Remote SDP: v=0 o=- 1460126829 1 IN IP4 85.*.*.4 s=portsip.com c=IN IP4 52.*.*.177 t=0 0 m=audio 40082 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=nortpproxy:yes
2016-04-08 10:47:10.503262 [DEBUG] sofia.c:7125 (sofia/external/ 8@sip0.MY_DOMAIN.com) State Change CS_NEW -> CS_INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:492 (sofia/external/8@sip0.MY_DOMAIN.com) State NEW 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:516 (sofia/external/8@sip0.MY_DOMAIN.com) State INIT 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:88 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:40 sofia/external/8@sip0.MY_DOMAIN.com Standard INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:48 (sofia/external/8@sip0.MY_DOMAIN.com) State Change CS_INIT -> CS_ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:516 (sofia/external/8@sip0.MY_DOMAIN.com) State INIT going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_channel.c:2247 (sofia/external/ 8@sip0.MY_DOMAIN.com) Callstate Change DOWN -> RINGING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/8@sip0.MY_DOMAIN.com) State ROUTING 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:141 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:166 sofia/external/8@sip0.MY_DOMAIN.com Standard ROUTING 2016-04-08 10:47:10.503262 [INFO] mod_dialplan_xml.c:637 Processing 8 <8>->7906******* in context public Dialplan: sofia/external/8@sip0.MY_DOMAIN.com parsing [public->from_opensips] continue=false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Regex (PASS) [from_opensips] network_addr(172.31.0.169) =~ /^172\.31\.0\.169$/ break=on-false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Action transfer(${destination_number} XML default) 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:216 (sofia/external/8@sip0.MY_DOMAIN.com) State Change CS_ROUTING -> CS_EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/8@sip0.MY_DOMAIN.com) State ROUTING going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:539 (sofia/external/8@sip0.MY_DOMAIN.com) State EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:196 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:258 sofia/external/8@sip0.MY_DOMAIN.com Standard EXECUTE EXECUTE sofia/external/8@sip0.MY_DOMAIN.com transfer(7906******* XML default) 2016-04-08 10:47:10.503262 [DEBUG] switch_ivr.c:2085 (sofia/external/ 8@sip0.MY_DOMAIN.com) State Change CS_EXECUTE -> CS_ROUTING 2016-04-08 10:47:10.503262 [NOTICE] switch_ivr.c:2092 Transfer sofia/external/8@sip0.MY_DOMAIN.com to XML[7906*******@default] 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:539 (sofia/external/8@sip0.MY_DOMAIN.com) State EXECUTE going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/8@sip0.MY_DOMAIN.com) State ROUTING 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:141 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:166 sofia/external/8@sip0.MY_DOMAIN.com Standard ROUTING 2016-04-08 10:47:10.503262 [INFO] mod_dialplan_xml.c:637 Processing 8 <8>->7906******* in context default Dialplan: sofia/external/8@sip0.MY_DOMAIN.com parsing [default->unloop] continue=false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com parsing [default->tod_example] continue=true Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Action set(open=true) Dialplan: sofia/external/8@sip0.MY_DOMAIN.com parsing [default->outbound_calls_to_freelycall] continue=false Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Regex (PASS) [outbound_calls_to_freelycall] destination_number(7906*******) =~ /^(.+)/ break=on-true Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Action set(hangup_after_bridge=true) Dialplan: sofia/external/8@sip0.MY_DOMAIN.com Action bridge(sofia/gateway/freelycall.com/7906*******) 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:216 (sofia/external/8@sip0.MY_DOMAIN.com) State Change CS_ROUTING -> CS_EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/8@sip0.MY_DOMAIN.com) State ROUTING going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:539 (sofia/external/8@sip0.MY_DOMAIN.com) State EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:196 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA EXECUTE 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:258 sofia/external/8@sip0.MY_DOMAIN.com Standard EXECUTE EXECUTE sofia/external/8@sip0.MY_DOMAIN.com set(open=true) 2016-04-08 10:47:10.503262 [DEBUG] mod_dptools.c:1498 SET sofia/external/ 8@sip0.MY_DOMAIN.com [open]=[true] EXECUTE sofia/external/8@sip0.MY_DOMAIN.com set(hangup_after_bridge=true) 2016-04-08 10:47:10.503262 [DEBUG] mod_dptools.c:1498 SET sofia/external/ 8@sip0.MY_DOMAIN.com [hangup_after_bridge]=[true] EXECUTE sofia/external/8@sip0.MY_DOMAIN.com bridge(sofia/gateway/ freelycall.com/7906*******) 2016-04-08 10:47:10.503262 [DEBUG] switch_ivr_originate.c:2128 Parsing global variables 2016-04-08 10:47:10.503262 [NOTICE] switch_channel.c:1101 New Channel sofia/external/7906******* [c619366c-fd98-11e5-a35c-831849fc41a3] 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:4776 (sofia/external/7906*******) State Change CS_NEW -> CS_INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:516 (sofia/external/7906*******) State INIT 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:88 sofia/external/7906******* SOFIA INIT 2016-04-08 10:47:10.503262 [DEBUG] sofia_glue.c:1257 sofia/external/7906******* sending invite version: 1.6.6 64bit Local SDP: v=0 o=FreeSWITCH 1460100428 1460100429 IN IP4 52.*.*.198 s=FreeSWITCH c=IN IP4 52.*.*.198 t=0 0 m=audio 26402 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv
2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:40 sofia/external/7906******* Standard INIT 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:48 (sofia/external/7906*******) State Change CS_INIT -> CS_ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:516 (sofia/external/7906*******) State INIT going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_ROUTING 2016-04-08 10:47:10.503262 [DEBUG] sofia.c:6760 Channel sofia/external/7906******* entering state [calling][0] 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/7906*******) State ROUTING 2016-04-08 10:47:10.503262 [DEBUG] mod_sofia.c:141 sofia/external/7906******* SOFIA ROUTING 2016-04-08 10:47:10.503262 [DEBUG] switch_ivr_originate.c:67 (sofia/external/7906*******) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:532 (sofia/external/7906*******) State ROUTING going to sleep 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_CONSUME_MEDIA 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:551 (sofia/external/7906*******) State CONSUME_MEDIA 2016-04-08 10:47:10.503262 [DEBUG] switch_core_state_machine.c:551 (sofia/external/7906*******) State CONSUME_MEDIA going to sleep 2016-04-08 10:47:17.443282 [DEBUG] sofia.c:6760 Channel sofia/external/7906******* entering state [proceeding][183] 2016-04-08 10:47:17.443282 [DEBUG] sofia.c:6770 Remote SDP: v=0 o=root 153112258 153112258 IN IP4 178.*.*.12 s=Asterisk PBX 11.11.0 c=IN IP4 178.*.*.12 t=0 0 m=audio 17362 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4077 Set telephone-event payload to 101@8000 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:2906 Set Codec sofia/external/7906******* PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2016-04-08 10:47:17.443282 [DEBUG] switch_core_codec.c:111 sofia/external/7906******* Original read codec set to PCMA:8 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4429 Set telephone-event payload to 101@8000 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4485 sofia/external/7906******* Set 2833 dtmf send payload to 101 recv payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6033 AUDIO RTP [sofia/external/7906*******] 172.31.22.124 port 26402 -> 178.*.*.12 port 17362 codec: 8 ms: 20 2016-04-08 10:47:17.443282 [DEBUG] switch_rtp.c:3802 Starting timer [soft] 160 bytes per 20ms 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6332 sofia/external/7906******* Set 2833 dtmf send payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6339 sofia/external/7906******* Set 2833 dtmf receive payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6362 sofia/external/7906******* Set rtp dtmf delay to 40 2016-04-08 10:47:17.443282 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/7906*******! 2016-04-08 10:47:17.443282 [DEBUG] switch_channel.c:3468 (sofia/external/7906*******) Callstate Change DOWN -> EARLY 2016-04-08 10:47:17.443282 [INFO] switch_ivr_originate.c:3557 Sending early media 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4077 Set telephone-event payload to 101@8000 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:2906 Set Codec sofia/external/8@sip0.MY_DOMAIN.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2016-04-08 10:47:17.443282 [DEBUG] switch_core_codec.c:111 sofia/external/ 8@sip0.MY_DOMAIN.com Original read codec set to PCMA:8 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4429 Set telephone-event payload to 101@8000 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:4485 sofia/external/8@sip0.MY_DOMAIN.com Set 2833 dtmf send payload to 101 recv payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6033 AUDIO RTP [sofia/external/8@sip0.MY_DOMAIN.com] 172.31.22.124 port 30630 -> 52.*.*.177 port 40082 codec: 8 ms: 20 2016-04-08 10:47:17.443282 [DEBUG] switch_rtp.c:3802 Starting timer [soft] 160 bytes per 20ms 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6332 sofia/external/8@sip0.MY_DOMAIN.com Set 2833 dtmf send payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6339 sofia/external/8@sip0.MY_DOMAIN.com Set 2833 dtmf receive payload to 101 2016-04-08 10:47:17.443282 [DEBUG] switch_core_media.c:6362 sofia/external/8@sip0.MY_DOMAIN.com Set rtp dtmf delay to 40 2016-04-08 10:47:17.443282 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/8@sip0.MY_DOMAIN.com! 2016-04-08 10:47:17.443282 [DEBUG] switch_channel.c:3468 (sofia/external/ 8@sip0.MY_DOMAIN.com) Callstate Change RINGING -> EARLY 2016-04-08 10:47:17.443282 [DEBUG] mod_sofia.c:2330 Ring SDP: v=0 o=FreeSWITCH 1460096207 1460096208 IN IP4 52.*.*.198 s=FreeSWITCH c=IN IP4 52.*.*.198 t=0 0 m=audio 30630 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv
2016-04-08 10:47:17.443282 [DEBUG] sofia.c:6760 Channel sofia/external/ 8@sip0.MY_DOMAIN.com entering state [early][183] 2016-04-08 10:47:17.443282 [DEBUG] switch_ivr_originate.c:3608 Originate Resulted in Success: [sofia/external/7906*******] 2016-04-08 10:47:17.463254 [DEBUG] switch_ivr_bridge.c:1591 (sofia/external/7906*******) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2016-04-08 10:47:17.463254 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_EXCHANGE_MEDIA 2016-04-08 10:47:17.463254 [DEBUG] switch_core_state_machine.c:542 (sofia/external/7906*******) State EXCHANGE_MEDIA 2016-04-08 10:47:17.463254 [DEBUG] mod_sofia.c:613 SOFIA EXCHANGE_MEDIA 2016-04-08 10:47:17.503264 [DEBUG] switch_rtp.c:6654 Correct audio ip/port confirmed. 2016-04-08 10:47:17.663261 [DEBUG] switch_rtp.c:6654 Correct audio ip/port confirmed. 2016-04-08 10:47:21.323279 [DEBUG] sofia.c:6760 Channel sofia/external/7906******* entering state [completing][200] 2016-04-08 10:47:21.323279 [DEBUG] sofia.c:6767 Duplicate SDP v=0 o=root 153112258 153112258 IN IP4 178.*.*.12 s=Asterisk PBX 11.11.0 c=IN IP4 178.*.*.12 t=0 0 m=audio 17362 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2016-04-08 10:47:21.323279 [DEBUG] sofia.c:6760 Channel sofia/external/7906******* entering state [ready][200] 2016-04-08 10:47:21.323279 [NOTICE] sofia.c:7665 Channel [sofia/external/7906*******] has been answered 2016-04-08 10:47:21.323279 [DEBUG] switch_channel.c:3767 (sofia/external/7906*******) Callstate Change EARLY -> ACTIVE 2016-04-08 10:47:21.323279 [DEBUG] mod_sofia.c:799 Local SDP sofia/external/8@sip0.MY_DOMAIN.com: v=0 o=FreeSWITCH 1460096207 1460096209 IN IP4 52.*.*.198 s=FreeSWITCH c=IN IP4 52.*.*.198 t=0 0 m=audio 30630 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv
2016-04-08 10:47:21.323279 [DEBUG] sofia.c:6760 Channel sofia/external/ 8@sip0.MY_DOMAIN.com entering state [completed][200] 2016-04-08 10:47:21.323279 [NOTICE] switch_ivr_bridge.c:616 Channel [sofia/external/8@sip0.MY_DOMAIN.com] has been answered 2016-04-08 10:47:21.323279 [DEBUG] switch_channel.c:3767 (sofia/external/ 8@sip0.MY_DOMAIN.com) Callstate Change EARLY -> ACTIVE 2016-04-08 10:47:21.383279 [DEBUG] switch_rtp.c:6654 Correct audio ip/port confirmed. 2016-04-08 10:47:21.423259 [DEBUG] switch_rtp.c:6654 Correct audio ip/port confirmed.
*And after 30 seconds:* 2016-04-08 10:47:53.343283 [DEBUG] sofia.c:6760 Channel sofia/external/ 8@sip0.MY_DOMAIN.com entering state [terminating][0] 2016-04-08 10:47:53.343283 [NOTICE] sofia.c:7779 Hangup sofia/external/ 8@sip0.MY_DOMAIN.com [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2016-04-08 10:47:53.343283 [DEBUG] switch_ivr_bridge.c:699 sofia/external/ 8@sip0.MY_DOMAIN.com ending bridge by request from write function 2016-04-08 10:47:53.343283 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [sofia/external/7906*******] 2016-04-08 10:47:53.343283 [NOTICE] switch_ivr_bridge.c:881 Hangup sofia/external/7906******* [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:542 (sofia/external/7906*******) State EXCHANGE_MEDIA going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_HANGUP 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:739 (sofia/external/7906*******) Callstate Change ACTIVE -> HANGUP 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:741 (sofia/external/7906*******) State HANGUP 2016-04-08 10:47:53.343283 [DEBUG] mod_sofia.c:431 Channel sofia/external/7906******* hanging up, cause: NORMAL_CLEARING 2016-04-08 10:47:53.343283 [DEBUG] mod_sofia.c:484 Sending BYE to sofia/external/7906******* 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:60 sofia/external/7906******* Standard HANGUP, cause: NORMAL_CLEARING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:741 (sofia/external/7906*******) State HANGUP going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:508 (sofia/external/7906*******) State Change CS_HANGUP -> CS_REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:473 (sofia/external/7906*******) Running State Change CS_REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:827 (sofia/external/7906*******) State REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:104 sofia/external/7906******* Standard REPORTING, cause: NORMAL_CLEARING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:827 (sofia/external/7906*******) State REPORTING going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:499 (sofia/external/7906*******) State Change CS_REPORTING -> CS_DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_session.c:1646 Session 2 (sofia/external/7906*******) Locked, Waiting on external entities 2016-04-08 10:47:53.343283 [DEBUG] switch_ivr_bridge.c:705 sofia/external/ 8@sip0.MY_DOMAIN.com ending bridge by request from read function 2016-04-08 10:47:53.343283 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [sofia/external/8@sip0.MY_DOMAIN.com] 2016-04-08 10:47:53.343283 [DEBUG] switch_ivr_bridge.c:1692 sofia/external/8@sip0.MY_DOMAIN.com skip receive message [UNBRIDGE] (channel is hungup already) 2016-04-08 10:47:53.343283 [DEBUG] switch_core_session.c:2796 sofia/external/8@sip0.MY_DOMAIN.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:539 (sofia/external/8@sip0.MY_DOMAIN.com) State EXECUTE going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_HANGUP 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:739 (sofia/external/8@sip0.MY_DOMAIN.com) Callstate Change ACTIVE -> HANGUP 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:741 (sofia/external/8@sip0.MY_DOMAIN.com) State HANGUP 2016-04-08 10:47:53.343283 [DEBUG] mod_sofia.c:431 Channel sofia/external/ 8@sip0.MY_DOMAIN.com hanging up, cause: NORMAL_UNSPECIFIED 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:60 sofia/external/8@sip0.MY_DOMAIN.com Standard HANGUP, cause: NORMAL_UNSPECIFIED 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:741 (sofia/external/8@sip0.MY_DOMAIN.com) State HANGUP going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:508 (sofia/external/8@sip0.MY_DOMAIN.com) State Change CS_HANGUP -> CS_REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:473 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:827 (sofia/external/8@sip0.MY_DOMAIN.com) State REPORTING 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:104 sofia/external/8@sip0.MY_DOMAIN.com Standard REPORTING, cause: NORMAL_UNSPECIFIED 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:827 (sofia/external/8@sip0.MY_DOMAIN.com) State REPORTING going to sleep 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:499 (sofia/external/8@sip0.MY_DOMAIN.com) State Change CS_REPORTING -> CS_DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_session.c:1646 Session 1 (sofia/external/8@sip0.MY_DOMAIN.com) Locked, Waiting on external entities 2016-04-08 10:47:53.343283 [NOTICE] switch_core_session.c:1664 Session 1 (sofia/external/8@sip0.MY_DOMAIN.com) Ended 2016-04-08 10:47:53.343283 [NOTICE] switch_core_session.c:1668 Close Channel sofia/external/8@sip0.MY_DOMAIN.com [CS_DESTROY] 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:630 (sofia/external/8@sip0.MY_DOMAIN.com) Running State Change CS_DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:640 (sofia/external/8@sip0.MY_DOMAIN.com) State DESTROY 2016-04-08 10:47:53.343283 [DEBUG] mod_sofia.c:341 sofia/external/ 8@sip0.MY_DOMAIN.com SOFIA DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:111 sofia/external/8@sip0.MY_DOMAIN.com Standard DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:640 (sofia/external/8@sip0.MY_DOMAIN.com) State DESTROY going to sleep 2016-04-08 10:47:53.343283 [NOTICE] switch_core_session.c:1664 Session 2 (sofia/external/7906*******) Ended 2016-04-08 10:47:53.343283 [NOTICE] switch_core_session.c:1668 Close Channel sofia/external/7906******* [CS_DESTROY] 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:630 (sofia/external/7906*******) Running State Change CS_DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:640 (sofia/external/7906*******) State DESTROY 2016-04-08 10:47:53.343283 [DEBUG] mod_sofia.c:341 sofia/external/7906******* SOFIA DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:111 sofia/external/7906******* Standard DESTROY 2016-04-08 10:47:53.343283 [DEBUG] switch_core_state_machine.c:640 (sofia/external/7906*******) State DESTROY going to sleep
2016-04-08 17:37 GMT+03:00 Jurijs Ivolga <jurijs.ivolga@gmail.com>:
Hi,
I would recommend you to capture SIP packets during call on Freeswitch server and send it here, I will take a look on it.
With kind regards,
Jurijs
On Fri, Apr 8, 2016 at 5:34 PM, Стас Тельнов <stasan89@gmail.com> wrote:
I already tried disabling timers, does not work.
2016-04-08 17:19 GMT+03:00 Oleg Stolyar <olegstolyar@gmail.com>:
Try disabling session timers in the sip profile. I think that line is commented out by default, so uncomment it.
<param name="enable-timer" value="false"/>
On Fri, Apr 8, 2016 at 6:59 AM, Стас Тельнов <stasan89@gmail.com> wrote:
Hello.
When using a call or conference through sip — freeswitch with external provider there is a problem – the call is interrupted in 30 seconds. Though the sound goes all right. I think that it caused by the NAT settings for freeswitch, but I don't understand how to adjust it correctly. At start of freeswitch I see the following mistakes in the tracking data: 2016-04-08 07:04:50.903529 [INFO] switch_nat.c:417 Scanning for NAT 2016-04-08 07:04:50.903678 [DEBUG] switch_nat.c:170 Checking for PMP 1/5 2016-04-08 07:04:51.903843 [DEBUG] switch_nat.c:170 Checking for PMP 2/5 2016-04-08 07:04:52.904023 [DEBUG] switch_nat.c:170 Checking for PMP 3/5 2016-04-08 07:04:53.904185 [DEBUG] switch_nat.c:170 Checking for PMP 4/5 2016-04-08 07:04:54.904360 [DEBUG] switch_nat.c:170 Checking for PMP 5/5 2016-04-08 07:04:55.904495 [ERR] switch_nat.c:199 Error checking for PMP [general error] 2016-04-08 07:04:55.904548 [DEBUG] switch_nat.c:422 Checking for UPnP 2016-04-08 07:05:07.905219 [INFO] switch_nat.c:438 No PMP or UPnP NAT devices detected!
Despite of this mistake, conference communication between two internal users works normally. The problem arises at a call through external provider.
We have the following architecture: In a cloud of Amazon EC2 there are 2 servers – opensips and freeswitch, both for NAT for external clients, but have an opportunity to work with each other directly. opensips has the internal address 172.31.0.169 and external 52. *.*.177 freeswitch has the internal address 172.31.22.124 and external 52. *.*.198
In fact, freeswitch acts only for conferences, and is ready for use of a remote DB on opensips. The auto-nat settings by default didn't work. The problem is in the external profile settings as far as I understand.
I have filled and created the following configuration: vars.xml <X-PRE-PROCESS cmd="set" data="bind_server_ip=auto”/> <X-PRE-PROCESS cmd="set" data="external_rtp_ip=52.*.*.198”/> <!— public freeswitch ip —> <X-PRE-PROCESS cmd="set" data="external_sip_ip=52.*.*.198”/> <!— public freeswitch ip —> <!-- External SIP Profile --> <X-PRE-PROCESS cmd="set" data="external_auth_calls=true"/> <X-PRE-PROCESS cmd="set" data="external_sip_port=5060"/> <X-PRE-PROCESS cmd="set" data="external_tls_port=5061"/> <X-PRE-PROCESS cmd="set" data="external_ssl_enable=true"/> <X-PRE-PROCESS cmd="set" data="external_ssl_dir=$${base_dir}/conf/tls"/>
sip_profile/external.xml <param name="rtp-ip" value="$${local_ip_v4}"/> <param name="sip-ip" value="$${local_ip_v4}"/>
<param name="ext-rtp-ip" value=“52.*.*.198”/> <!— public freeswitch ip —> <param name="ext-sip-ip" value=“52.*.*.198”/> <!— public freeswitch ip —> In this sip_profile/external.xml I tried to fill rtp-ip/sip-ip and ext-rtp-ip/ext-sip-ip with the corresponding addresses of opensips server (that would be logical), but in that case conferences didn't work at all and errors below appeared: [ERR] sofia.c:2935 Error Creating SIP UA for profile: external ... Also I tried to put such configuration: <param name="rtp-ip" value="auto"/> <param name="sip-ip" value="52.*.*.198”/> but it also hasn't helped to solve the problem.
autoload_configs/switch.conf.xml <param name="rtp-start-port" value="16384"/> <param name="rtp-end-port" value="32768"/>
"sofia status" looks as follows: Name Type Data State
================================================================================================= 172.31.22.124 alias internal ALIASED external profile sip:mod_sofia@52.*.*.198:5060 RUNNING (0) external profile sip:mod_sofia@52.*.*.198:5061 RUNNING (0) (TLS) external::*********.com gateway sip:USER@*********.com REGED internal profile sip:mod_sofia@52.*.*.198:5080 RUNNING (0) internal profile sip:mod_sofia@52.*.*.198:5081 RUNNING (0) (TLS)
================================================================================================= 2 profiles 1 alias
"sofia status profile external" looks as follows:
================================================================================================= Name external Domain Name N/A Auto-NAT false DBName sofia_reg_external Pres Hosts Dialplan XML Context public Challenge Realm auto_to RTP-IP 172.31.22.124 Ext-RTP-IP 52.*.*.198 SIP-IP 172.31.22.124 Ext-SIP-IP 52.*.*.198 URL sip:mod_sofia@52.*.*.198:5060 BIND-URL sip:mod_sofia@52. *.*.198:5060;maddr=172.31.22.124;transport=udp,tcp TLS-URL sip:mod_sofia@52.*.*.198:5061 TLS-BIND-URL sips:mod_sofia@52. *.*.198:5061;maddr=172.31.22.124;transport=tls HOLD-MUSIC local_stream://moh OUTBOUND-PROXY N/A CODECS IN PCMA CODECS OUT PCMA TEL-EVENT 101 DTMF-MODE rfc2833 CNG 13 SESSION-TO 0 MAX-DIALOG 0 NOMEDIA false LATE-NEG true PROXY-MEDIA false ZRTP-PASSTHRU true AGGRESSIVENAT false CALLS-IN 0 FAILED-CALLS-IN 0 CALLS-OUT 0 FAILED-CALLS-OUT 0 REGISTRATIONS 0
What do I adjust wrong? Whether there is some opportunity, to tell freeswitch not to break off a call in 30 seconds even if NAT isn't adjusted?
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE: http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org