<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=utf-8">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hello!<br>
<br>
Very strange, some time ago this works, but now not... and I don't
know where I was made mistake...<br>
<br>
From FS CLI do command<br>
<br>
<b>originate {ignore_early_media=true}sofia/internal/00294539100%
&bridge(sofia/gateway/voip_provider/919262417024@voip_provider)</b><br>
<br>
Call to user 00294539100 established, but second call to external is
dropped before send INVITE... (local cause NORMAL_UNSPECIFIED)<br>
<br>
Could someone give me idea where is a problem?<br>
<br>
<br>
<br>
<br>
Trace here<br>
<br>
<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_ivr_originate.c:2100
Parsing global variables<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_event.c:1698 Parsing
variable [ignore_early_media]=[true]<br>
2015-07-15 10:09:19.375204 [NOTICE] switch_channel.c:1075 New
Channel sofia/internal/00294539100
[680855ef-9973-43c4-bb9d-7ee1dd27d392]<br>
2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:4701
(sofia/internal/00294539100) State Change CS_NEW -> CS_INIT<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472
(sofia/internal/00294539100) Running State Change CS_INIT<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:512
(sofia/internal/00294539100) State INIT<br>
2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:87
sofia/internal/00294539100 SOFIA INIT<br>
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<br>
Local SDP:<br>
v=0<br>
o=FreeSWITCH 1436918327 1436918328 IN IP4 194.87.7.17<br>
s=FreeSWITCH<br>
c=IN IP4 194.87.7.17<br>
t=0 0<br>
m=audio 22232 RTP/AVP 102 9 0 8 3 101 13<br>
a=rtpmap:102 opus/48000/2<br>
a=fmtp:102 useinbandfec=1; usedtx=1; maxaveragebitrate=30000;
maxplaybackrate=48000; ptime=20; minptime=20; maxptime=20;
samplerate=48000<br>
a=rtpmap:9 G722/8000<br>
a=rtpmap:0 PCMU/8000<br>
a=rtpmap:8 PCMA/8000<br>
a=rtpmap:3 GSM/8000<br>
a=rtpmap:101 telephone-event/8000<br>
a=fmtp:101 0-16<br>
a=ptime:20<br>
a=sendrecv<br>
m=video 29716 RTP/AVP 103<br>
a=rtpmap:103 VP8/90000<br>
<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:40
sofia/internal/00294539100 Standard INIT<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/00294539100) State Change CS_INIT -> CS_ROUTING<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:512
(sofia/internal/00294539100) State INIT going to sleep<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472
(sofia/internal/00294539100) Running State Change CS_ROUTING<br>
2015-07-15 10:09:19.375204 [DEBUG] sofia.c:6627 Channel
sofia/internal/00294539100 entering state [calling][0]<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:528
(sofia/internal/00294539100) State ROUTING<br>
2015-07-15 10:09:19.375204 [DEBUG] mod_sofia.c:123
sofia/internal/00294539100 SOFIA ROUTING<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/00294539100) State Change CS_ROUTING ->
CS_CONSUME_MEDIA<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_session.c:1396 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:528
(sofia/internal/00294539100) State ROUTING going to sleep<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:472
(sofia/internal/00294539100) Running State Change CS_CONSUME_MEDIA<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:547
(sofia/internal/00294539100) State CONSUME_MEDIA<br>
2015-07-15 10:09:19.375204 [DEBUG] switch_core_state_machine.c:547
(sofia/internal/00294539100) State CONSUME_MEDIA going to sleep<br>
2015-07-15 10:09:19.455217 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.455217 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:19.455217 [DEBUG] sofia.c:6627 Channel
sofia/internal/00294539100 entering state [proceeding][180]<br>
2015-07-15 10:09:19.455217 [NOTICE] sofia.c:6729 Ring-Ready
sofia/internal/00294539100!<br>
2015-07-15 10:09:19.455217 [DEBUG] switch_channel.c:3297
(sofia/internal/00294539100) Callstate Change DOWN -> RINGING<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6627 Channel
sofia/internal/00294539100 entering state [completing][200]<br>
2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6637 Remote SDP:<br>
v=0<br>
o=floxent 3645929363 1 IN IP4 192.168.223.220<br>
s=sflphone<br>
c=IN IP4 192.168.223.220<br>
t=0 0<br>
m=audio 28878 RTP/AVP 9 101<br>
a=rtpmap:9 G722/8000<br>
a=rtpmap:101 telephone-event/8000<br>
a=fmtp:101 0-15<br>
a=rtcp:28879 IN IP4 192.168.223.220<br>
m=video 0 RTP/AVP 103<br>
<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_session.c:1061 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:22.075203 [DEBUG] sofia.c:6627 Channel
sofia/internal/00294539100 entering state [ready][200]<br>
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]<br>
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]<br>
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<br>
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]<br>
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]<br>
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]<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3588 Set
telephone-event payload to 101<br>
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<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_codec.c:111
sofia/internal/00294539100 Original read codec set to G722:9<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:3926 Set 2833
dtmf send payload to 101<br>
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<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_rtp.c:3569 Starting timer
[soft] 160 bytes per 20ms<br>
2015-07-15 10:09:22.075203 [INFO] switch_core_media.c:5388
Activating RTCP PORT 28879<br>
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<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_rtp.c:2349 Setting RTCP
remote addr to 192.168.223.220:28879<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5469 Set 2833
dtmf send payload to 101<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5475 Set 2833
dtmf receive payload to 101<br>
2015-07-15 10:09:22.075203 [DEBUG] switch_core_media.c:5497
sofia/internal/00294539100 Set rtp dtmf delay to 40<br>
<b>2015-07-15 10:09:22.075203 [NOTICE] sofia.c:7488 Channel
[sofia/internal/00294539100] has been answered</b><br>
2015-07-15 10:09:22.075203 [DEBUG] switch_channel.c:3711
(sofia/internal/00294539100) Callstate Change RINGING -> ACTIVE<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:3577
Originate Resulted in Success: [sofia/internal/00294539100]<br>
2015-07-15 10:09:22.095205 [INFO] switch_channel.c:3082
sofia/internal/00294539100 Flipping CID from "" <0000000000>
to "Outbound Call" <00294539100%><br>
2015-07-15 10:09:22.095205 [DEBUG] mod_commands.c:4469
(sofia/internal/00294539100) State Change CS_CONSUME_MEDIA ->
CS_EXECUTE<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/internal/00294539100 [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
(sofia/internal/00294539100) Running State Change CS_EXECUTE<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:535
(sofia/internal/00294539100) State EXECUTE<br>
2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:178
sofia/internal/00294539100 SOFIA EXECUTE<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:258
sofia/internal/00294539100 Standard EXECUTE<br>
EXECUTE sofia/internal/00294539100
bridge(sofia/gateway/voip_provider/919262417024@voip_provider)<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:1786
(sofia/internal/00294539100) Callstate Change ACTIVE -> RING_WAIT<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:2100
Parsing global variables<br>
2015-07-15 10:09:22.095205 [NOTICE] switch_channel.c:1075 New
Channel sofia/external/919262417024@voip_provider
[32799f05-3018-4a48-bea4-1d3cc3700835]<br>
2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:4701
(sofia/external/919262417024@voip_provider) State Change CS_NEW
-> CS_INIT<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
(sofia/external/919262417024@voip_provider) Running State Change
CS_INIT<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512
(sofia/external/919262417024@voip_provider) State INIT<br>
2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:87
sofia/external/919262417024@voip_provider SOFIA INIT<br>
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<br>
Local SDP:<br>
v=0<br>
o=FreeSWITCH 1436921310 1436921311 IN IP4 194.87.7.17<br>
s=FreeSWITCH<br>
c=IN IP4 194.87.7.17<br>
t=0 0<br>
m=audio 19252 RTP/AVP 9 0 8 3 101 13<br>
a=rtpmap:9 G722/8000<br>
a=rtpmap:0 PCMU/8000<br>
a=rtpmap:8 PCMA/8000<br>
a=rtpmap:3 GSM/8000<br>
a=rtpmap:101 telephone-event/8000<br>
a=fmtp:101 0-16<br>
a=ptime:20<br>
a=sendrecv<br>
m=video 31754 RTP/AVP 103<br>
a=rtpmap:103 VP8/90000<br>
<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:40
sofia/external/919262417024@voip_provider Standard INIT<br>
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<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:512
(sofia/external/919262417024@voip_provider) State INIT going to
sleep<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1061 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
(sofia/external/919262417024@voip_provider) Running State Change
CS_ROUTING<br>
2015-07-15 10:09:22.095205 [DEBUG] sofia.c:6627 Channel
sofia/external/919262417024@voip_provider entering state
[terminated][900]<br>
<b>2015-07-15 10:09:22.095205 [NOTICE] sofia.c:7543 Hangup
sofia/external/919262417024@voip_provider [CS_ROUTING]
[NORMAL_UNSPECIFIED]</b><br>
2015-07-15 10:09:22.095205 [DEBUG] switch_ivr_originate.c:3720
Originate Resulted in Error Cause: 31 [NORMAL_UNSPECIFIED]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:3242 Send signal
sofia/external/919262417024@voip_provider [KILL]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528
(sofia/external/919262417024@voip_provider) State ROUTING<br>
2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:123
sofia/external/919262417024@voip_provider SOFIA ROUTING<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:528
(sofia/external/919262417024@voip_provider) State ROUTING going to
sleep<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
(sofia/external/919262417024@voip_provider) Running State Change
CS_HANGUP<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:735
(sofia/external/919262417024@voip_provider) Callstate Change DOWN
-> HANGUP<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737
(sofia/external/919262417024@voip_provider) State HANGUP<br>
2015-07-15 10:09:22.095205 [DEBUG] mod_sofia.c:413 Channel
sofia/external/919262417024@voip_provider hanging up, cause:
NORMAL_UNSPECIFIED<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:60
sofia/external/919262417024@voip_provider Standard HANGUP, cause:
NORMAL_UNSPECIFIED<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:737
(sofia/external/919262417024@voip_provider) State HANGUP going to
sleep<br>
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<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:472
(sofia/external/919262417024@voip_provider) Running State Change
CS_REPORTING<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823
(sofia/external/919262417024@voip_provider) State REPORTING<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:104
sofia/external/919262417024@voip_provider Standard REPORTING, cause:
NORMAL_UNSPECIFIED<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_state_machine.c:823
(sofia/external/919262417024@voip_provider) State REPORTING going to
sleep<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:1999
(sofia/internal/00294539100) Callstate Change RING_WAIT -> ACTIVE<br>
2015-07-15 10:09:22.095205 [INFO] mod_dptools.c:3268 Originate
Failed. Cause: NORMAL_UNSPECIFIED<br>
2015-07-15 10:09:22.095205 [NOTICE] switch_channel.c:4747 Hangup
sofia/internal/00294539100 [CS_EXECUTE] [NORMAL_UNSPECIFIED]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_channel.c:3242 Send signal
sofia/internal/00294539100 [KILL]<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/internal/00294539100 [BREAK]<br>
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<br>
2015-07-15 10:09:22.095205 [DEBUG] switch_core_session.c:1396 Send
signal sofia/external/919262417024@voip_provider [BREAK]<br>
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<br>
2015-07-15 10:09:22.095205 [NOTICE] switch_core_session.c:1641
Session 202 (sofia/external/919262417024@voip_provider) Ended<br>
2015-07-15 10:09:22.095205 [NOTICE] switch_core_session.c:1645 Close
Channel sofia/external/919262417024@voip_provider [CS_DESTROY]<br>
<br>
</body>
</html>