[Freeswitch-users] Call thru external gate released before INVITE (NORMAL_UNSPECIFIED)
Peter Steinbach
lists at telefaks.de
Wed Jul 15 11:16:29 MSD 2015
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 at 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 at 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 at 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 at voip_provider
> [32799f05-3018-4a48-bea4-1d3cc3700835]
> 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:4701
> (sofia/external/919262417024 at 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 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
> (sofia/external/919262417024 at voip_provider) Running State Change CS_INIT
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512
> (sofia/external/919262417024 at voip_provider) State INIT
> 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:87
> sofia/external/919262417024 at voip_provider SOFIA INIT
> 2015-07-15 10:09:22.095205 [DEBUG] sofia_glue.c:1236
> sofia/external/919262417024 at 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 at voip_provider Standard INIT
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:48
> (sofia/external/919262417024 at 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 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512
> (sofia/external/919262417024 at 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 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send
> signal sofia/external/919262417024 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send
> signal sofia/external/919262417024 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
> (sofia/external/919262417024 at voip_provider) Running State Change
> CS_ROUTING
> 2015-07-15 10:09:22.095205 [DEBUG] sofia.c:6627 Channel
> sofia/external/919262417024 at voip_provider entering state [terminated][900]
> *2015-07-15 10:09:22.095205 [NOTICE] sofia.c:7543 Hangup
> sofia/external/919262417024 at 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 at voip_provider [KILL]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
> signal sofia/external/919262417024 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528
> (sofia/external/919262417024 at voip_provider) State ROUTING
> 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:123
> sofia/external/919262417024 at voip_provider SOFIA ROUTING
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528
> (sofia/external/919262417024 at voip_provider) State ROUTING going to sleep
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
> (sofia/external/919262417024 at voip_provider) Running State Change CS_HANGUP
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:735
> (sofia/external/919262417024 at voip_provider) Callstate Change DOWN ->
> HANGUP
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737
> (sofia/external/919262417024 at voip_provider) State HANGUP
> 2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:413 Channel
> sofia/external/919262417024 at voip_provider hanging up, cause:
> NORMAL_UNSPECIFIED
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:60
> sofia/external/919262417024 at voip_provider Standard HANGUP, cause:
> NORMAL_UNSPECIFIED
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737
> (sofia/external/919262417024 at voip_provider) State HANGUP going to sleep
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:504
> (sofia/external/919262417024 at 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 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
> (sofia/external/919262417024 at voip_provider) Running State Change
> CS_REPORTING
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823
> (sofia/external/919262417024 at voip_provider) State REPORTING
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:104
> sofia/external/919262417024 at voip_provider Standard REPORTING, cause:
> NORMAL_UNSPECIFIED
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823
> (sofia/external/919262417024 at 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 at 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 at voip_provider [BREAK]
> 2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1623 Session
> 202 (sofia/external/919262417024 at 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 at voip_provider) Ended
> 2015-07-15 10:09:22.095205 [NOTICE] switch_core_session.c:1645 Close
> Channel sofia/external/919262417024 at voip_provider [CS_DESTROY]
>
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150715/b87b68bf/attachment-0001.html
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list