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