Hello Dmitry, just some thoughts: Is your gateway voip_provider definded properly? Can you dial this number voip_to provider manually with originate &park()? Is the DNS lookup to voip_provider successfull? It may be usefull o make a pcap file and investigate with Wireshark. Best regards Peter On 07/15/15 08:24, Dmitry Mordovin wrote:
Hello!
Very strange, some time ago this works, but now not... and I don't know where I was made mistake...
From FS CLI do command
*originate {ignore_early_media=true}sofia/internal/00294539100% &bridge(sofia/gateway/voip_provider/919262417024@voip_provider)*
Call to user 00294539100 established, but second call to external is dropped before send INVITE... (local cause NORMAL_UNSPECIFIED)
Could someone give me idea where is a problem?
Trace here
2015-07-15 10:09:19.375204 [DEBUG] switch_ivr_originate.c:2100 Parsing global variables 2015-07-15 10:09:19.375204 [DEBUG] switch_event.c:1698 Parsing variable [ignore_early_media]=[true] 2015-07-15 10:09:19.375204 [NOTICE] switch_channel.c:1075 New Channel sofia/internal/00294539100 [680855ef-9973-43c4-bb9d-7ee1dd27d392] 2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:4701 (sofia/internal/00294539100) State Change CS_NEW -> CS_INIT 2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/00294539100) Running State Change CS_INIT 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/00294539100) State INIT 2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:87 sofia/internal/00294539100 SOFIA INIT freeswitch@internal> 2015-07-15 10:09:19.375204 [DEBUG] sofia_glue.c:1236 sofia/internal/00294539100 sending invite version: 1.5.15b git acdb1ca 2015-05-17 18:45:52Z 32bit Local SDP: v=0 o=FreeSWITCH 1436918327 1436918328 IN IP4 194.87.7.17 s=FreeSWITCH c=IN IP4 194.87.7.17 t=0 0 m=audio 22232 RTP/AVP 102 9 0 8 3 101 13 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; usedtx=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=20; maxptime=20; samplerate=48000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 29716 RTP/AVP 103 a=rtpmap:103 VP8/90000
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:40 sofia/internal/00294539100 Standard INIT 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/00294539100) State Change CS_INIT -> CS_ROUTING 2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/00294539100) State INIT going to sleep 2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/00294539100) Running State Change CS_ROUTING 2015-07-15 10:09:19.375204 [DEBUG] sofia.c:6627 Channel sofia/internal/00294539100 entering state [calling][0] 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/00294539100) State ROUTING 2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:123 sofia/internal/00294539100 SOFIA ROUTING 2015-07-15 10:09:19.375204 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/00294539100) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/00294539100) State ROUTING going to sleep 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/00294539100) Running State Change CS_CONSUME_MEDIA 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/00294539100) State CONSUME_MEDIA 2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/00294539100) State CONSUME_MEDIA going to sleep 2015-07-15 10:09:19.455217 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.455217 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:19.455217 [DEBUG] sofia.c:6627 Channel sofia/internal/00294539100 entering state [proceeding][180] 2015-07-15 10:09:19.455217 [NOTICE] sofia.c:6729 Ring-Ready sofia/internal/00294539100! 2015-07-15 10:09:19.455217 [DEBUG] switch_channel.c:3297 (sofia/internal/00294539100) Callstate Change DOWN -> RINGING 2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6627 Channel sofia/internal/00294539100 entering state [completing][200] 2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6637 Remote SDP: v=0 o=floxent 3645929363 1 IN IP4 192.168.223.220 s=sflphone c=IN IP4 192.168.223.220 t=0 0 m=audio 28878 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtcp:28879 IN IP4 192.168.223.220 m=video 0 RTP/AVP 103
2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6627 Channel sofia/internal/00294539100 entering state [ready][200] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3672 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3672 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3727 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3672 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3672 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3672 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3588 Set telephone-event payload to 101 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:2507 Set Codec sofia/internal/00294539100 G722/8000 20 ms 160 samples 64000 bits 1 channels 2015-07-15 10:09:22.075203 [DEBUG] switch_core_codec.c:111 sofia/internal/00294539100 Original read codec set to G722:9 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3926 Set 2833 dtmf send payload to 101 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5171 AUDIO RTP [sofia/internal/00294539100] 194.87.7.17 port 22232 -> 192.168.223.220 port 28878 codec: 9 ms: 20 2015-07-15 10:09:22.075203 [DEBUG] switch_rtp.c:3569 Starting timer [soft] 160 bytes per 20ms 2015-07-15 10:09:22.075203 [INFO] switch_core_media.c:5388 Activating RTCP PORT 28879 2015-07-15 10:09:22.075203 [DEBUG] switch_rtp.c:3919 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 28879 2015-07-15 10:09:22.075203 [DEBUG] switch_rtp.c:2349 Setting RTCP remote addr to 192.168.223.220:28879 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5469 Set 2833 dtmf send payload to 101 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5475 Set 2833 dtmf receive payload to 101 2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5497 sofia/internal/00294539100 Set rtp dtmf delay to 40 *2015-07-15 10:09:22.075203 [NOTICE] sofia.c:7488 Channel [sofia/internal/00294539100] has been answered* 2015-07-15 10:09:22.075203 [DEBUG] switch_channel.c:3711 (sofia/internal/00294539100) Callstate Change RINGING -> ACTIVE 2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:3577 Originate Resulted in Success: [sofia/internal/00294539100] 2015-07-15 10:09:22.095205 [INFO] switch_channel.c:3082 sofia/internal/00294539100 Flipping CID from "" <0000000000> to "Outbound Call" <00294539100%> 2015-07-15 10:09:22.095205 [DEBUG] mod_commands.c:4469 (sofia/internal/00294539100) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/00294539100) Running State Change CS_EXECUTE 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/00294539100) State EXECUTE 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:178 sofia/internal/00294539100 SOFIA EXECUTE 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:258 sofia/internal/00294539100 Standard EXECUTE EXECUTE sofia/internal/00294539100 bridge(sofia/gateway/voip_provider/919262417024@voip_provider) 2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:1786 (sofia/internal/00294539100) Callstate Change ACTIVE -> RING_WAIT 2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:2100 Parsing global variables 2015-07-15 10:09:22.095205 [NOTICE] switch_channel.c:1075 New Channel sofia/external/919262417024@voip_provider [32799f05-3018-4a48-bea4-1d3cc3700835] 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:4701 (sofia/external/919262417024@voip_provider) State Change CS_NEW -> CS_INIT 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472 (sofia/external/919262417024@voip_provider) Running State Change CS_INIT 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512 (sofia/external/919262417024@voip_provider) State INIT 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:87 sofia/external/919262417024@voip_provider SOFIA INIT 2015-07-15 10:09:22.095205 [DEBUG] sofia_glue.c:1236 sofia/external/919262417024@voip_provider sending invite version: 1.5.15b git acdb1ca 2015-05-17 18:45:52Z 32bit Local SDP: v=0 o=FreeSWITCH 1436921310 1436921311 IN IP4 194.87.7.17 s=FreeSWITCH c=IN IP4 194.87.7.17 t=0 0 m=audio 19252 RTP/AVP 9 0 8 3 101 13 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 31754 RTP/AVP 103 a=rtpmap:103 VP8/90000
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:40 sofia/external/919262417024@voip_provider Standard INIT 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:48 (sofia/external/919262417024@voip_provider) State Change CS_INIT -> CS_ROUTING 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512 (sofia/external/919262417024@voip_provider) State INIT going to sleep 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472 (sofia/external/919262417024@voip_provider) Running State Change CS_ROUTING 2015-07-15 10:09:22.095205 [DEBUG] sofia.c:6627 Channel sofia/external/919262417024@voip_provider entering state [terminated][900] *2015-07-15 10:09:22.095205 [NOTICE] sofia.c:7543 Hangup sofia/external/919262417024@voip_provider [CS_ROUTING] [NORMAL_UNSPECIFIED]* 2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:3720 Originate Resulted in Error Cause: 31 [NORMAL_UNSPECIFIED] 2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:3242 Send signal sofia/external/919262417024@voip_provider [KILL] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528 (sofia/external/919262417024@voip_provider) State ROUTING 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:123 sofia/external/919262417024@voip_provider SOFIA ROUTING 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528 (sofia/external/919262417024@voip_provider) State ROUTING going to sleep 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472 (sofia/external/919262417024@voip_provider) Running State Change CS_HANGUP 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:735 (sofia/external/919262417024@voip_provider) Callstate Change DOWN -> HANGUP 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737 (sofia/external/919262417024@voip_provider) State HANGUP 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:413 Channel sofia/external/919262417024@voip_provider hanging up, cause: NORMAL_UNSPECIFIED 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:60 sofia/external/919262417024@voip_provider Standard HANGUP, cause: NORMAL_UNSPECIFIED 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737 (sofia/external/919262417024@voip_provider) State HANGUP going to sleep 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:504 (sofia/external/919262417024@voip_provider) State Change CS_HANGUP -> CS_REPORTING 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472 (sofia/external/919262417024@voip_provider) Running State Change CS_REPORTING 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823 (sofia/external/919262417024@voip_provider) State REPORTING 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:104 sofia/external/919262417024@voip_provider Standard REPORTING, cause: NORMAL_UNSPECIFIED 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823 (sofia/external/919262417024@voip_provider) State REPORTING going to sleep 2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:1999 (sofia/internal/00294539100) Callstate Change RING_WAIT -> ACTIVE 2015-07-15 10:09:22.095205 [INFO] mod_dptools.c:3268 Originate Failed. Cause: NORMAL_UNSPECIFIED 2015-07-15 10:09:22.095205 [NOTICE] switch_channel.c:4747 Hangup sofia/internal/00294539100 [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:3242 Send signal sofia/internal/00294539100 [KILL] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/00294539100 [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:498 (sofia/external/919262417024@voip_provider) State Change CS_REPORTING -> CS_DESTROY 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/919262417024@voip_provider [BREAK] 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1623 Session 202 (sofia/external/919262417024@voip_provider) Locked, Waiting on external entities 2015-07-15 10:09:22.095205 [NOTICE] switch_core_session.c:1641 Session 202 (sofia/external/919262417024@voip_provider) Ended 2015-07-15 10:09:22.095205 [NOTICE] switch_core_session.c:1645 Close Channel sofia/external/919262417024@voip_provider [CS_DESTROY]
_________________________________________________________________________ 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
-- With kind regards Peter Steinbach Telefaks Services GmbH mailto:lists (att) telefaks.de Internet: www.telefaks.de