[Freeswitch-users] Call thru external gate released before INVITE (NORMAL_UNSPECIFIED)

Dmitry Mordovin dm at dwide.com
Wed Jul 15 10:24:14 MSD 2015 

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]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150715/3db13d08/attachment-0001.html

Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users mailing list