i have install new fusionPBX i m trying to send calls to PLIVO, but call HANGUP with NORMAL_CLEARING
billow are the logs ...
.
.
.
.
.
.
2017-12-14 09:33:38.605560 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/100@xxx.xxx.xxx.yz) State NEW
2017-12-14 09:33:38.605560 [DEBUG] sofia.c:2334 detaching session e61b48dd-834b-401b-b86b-723c529dd4a4
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:2442 Re-attaching to session e61b48dd-834b-401b-b86b-723c529dd4a4
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:9873 sofia/internal/100@xxx.xxx.xxx.yz receiving invite from 124.253.8.219:10000 version: 1.6.19 -36-7a77e0b 64bit
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:10044 IP 124.253.8.219 Rejected by acl "domains". Falling back to Digest auth.
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:11168 Setting NAT mode based on via received
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7084 Channel sofia/internal/100@xxx.xxx.xxx.yz entering state [received][100]
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=Z 0 0 IN IP4 192.168.1.14
s=Z
c=IN IP4 192.168.1.14
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/100@xxx.xxx.xxx.yz GSM/8000 20 ms 160 samples 13200 bits 1 channels
2017-12-14 09:33:38.885494 [DEBUG] switch_core_codec.c:111 sofia/internal/100@xxx.xxx.xxx.yz Original read codec set to GSM:3
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4767 sofia/internal/100@xxx.xxx.xxx.yz Set 2833 dtmf send payload to 101 recv payload to 101
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7507 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_NEW -> CS_INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_INIT (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100@xxx.xxx.xxx.yz) State INIT
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:90 sofia/internal/100@xxx.xxx.xxx.yz SOFIA INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100@xxx.xxx.xxx.yz Standard INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_INIT -> CS_ROUTING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100@xxx.xxx.xxx.yz) State INIT going to sleep
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_ROUTING (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_channel.c:2249 (sofia/internal/100@xxx.xxx.xxx.yz) Callstate Change DOWN -> RINGING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100@xxx.xxx.xxx.yz) State ROUTING
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:143 sofia/internal/100@xxx.xxx.xxx.yz SOFIA ROUTING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:236 sofia/internal/100@xxx.xxx.xxx.yz Standard ROUTING
2017-12-14 09:33:38.885494 [INFO] mod_dialplan_xml.c:637 Processing 100 <100>->XYZXYZXYZSD in context public
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz parsing [public->57720099005466363.zt.plivo.com.d11] continue=false
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Regex (PASS) [57720099005466363.zt.plivo.com.d11] destination_number(XYZXYZXYZSD) =~ /^(\d{11})$/ break=on-false
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(call_direction=inbound)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [call_direction]=[inbound]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(domain_uuid=858c5728-acb4-4004-8f43-15c090d1bb04) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(domain_uuid=858c5728-acb4-4004-8f43-15c090d1bb04)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [domain_uuid]=[858c5728-acb4-4004-8f43-15c090d1bb04]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(domain_name=xxx.xxx.xxx.yz) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(domain_name=xxx.xxx.xxx.yz)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [domain_name]=[xxx.xxx.xxx.yz]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(call_direction=outbound)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action unset(call_timeout)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(inherit_codec=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(ignore_display_updates=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(callee_id_number=XYZXYZXYZSD)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(continue_on_fail=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action bridge(sofia/gateway/c7dd0b64-8ff0-46f8-9bbc-8be282ba1073/XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_ROUTING -> CS_EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100@xxx.xxx.xxx.yz) State ROUTING going to sleep
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_EXECUTE (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100@xxx.xxx.xxx.yz) State EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:198 sofia/internal/100@xxx.xxx.xxx.yz SOFIA EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:328 sofia/internal/100@xxx.xxx.xxx.yz Standard EXECUTE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(sip_h_X-accountcode=xxx.xxx.xxx.yz)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [sip_h_X-accountcode]=[xxx.xxx.xxx.yz]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(call_direction=outbound)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [call_direction]=[outbound]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz unset(call_timeout)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(hangup_after_bridge=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [hangup_after_bridge]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(effective_caller_id_name=)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(effective_caller_id_number=2123727255)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [effective_caller_id_number]=[2123727255]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(inherit_codec=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [inherit_codec]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(ignore_display_updates=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [ignore_display_updates]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(callee_id_number=XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [callee_id_number]=[XYZXYZXYZSD]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(continue_on_fail=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [continue_on_fail]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz bridge(sofia/gateway/c7dd0b64-8ff0-46f8-9bbc-8be282ba1073/XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] switch_channel.c:1250 sofia/internal/100@xxx.xxx.xxx.yz EXPORTING[export_vars] [domain_name]=[xxx.xxx.xxx.yz] to event
2017-12-14 09:33:38.885494 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-12-14 09:33:38.885494 [NOTICE] switch_channel.c:1104 New Channel sofia/external/XYZXYZXYZSD [ceb04666-775e-4949-a92a-1b6e4fb48a70]
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:4819 (sofia/external/XYZXYZXYZSD) State Change CS_NEW -> CS_INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_INIT (Cur 2 Tot 7253)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/external/XYZXYZXYZSD) State INIT
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:90 sofia/external/XYZXYZXYZSD SOFIA INIT
2017-12-14 09:33:38.925463 [DEBUG] switch_core_media.c:9710 sofia/external/XYZXYZXYZSD Patched SDP
v=0
o=Z 0 0 IN IP4 192.168.1.14
s=Z
c=IN IP4 192.168.1.14
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
+++
v=0
o=FreeSWITCH 2632333171 2632333172 IN IP4 xxx.xxx.xxx.yz
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.yz
t=0 0
m=audio 28974 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.925463 [DEBUG] sofia_glue.c:1295 sofia/external/XYZXYZXYZSD sending invite version: 1.6.19 -36-7a77e0b 64bit
Local SDP:
v=0
o=FreeSWITCH 2632333171 2632333172 IN IP4 xxx.xxx.xxx.yz
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.yz
t=0 0
m=audio 28974 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:40 sofia/external/XYZXYZXYZSD Standard INIT
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XYZXYZXYZSD) State Change CS_INIT -> CS_ROUTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:627 (sofia/external/XYZXYZXYZSD) State INIT going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_ROUTING (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:643 (sofia/external/XYZXYZXYZSD) State ROUTING
2017-12-14 09:33:38.925463 [DEBUG] mod_sofia.c:143 sofia/external/XYZXYZXYZSD SOFIA ROUTING
2017-12-14 09:33:38.925463 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XYZXYZXYZSD) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:643 (sofia/external/XYZXYZXYZSD) State ROUTING going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:662 (sofia/external/XYZXYZXYZSD) State CONSUME_MEDIA
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:662 (sofia/external/XYZXYZXYZSD) State CONSUME_MEDIA going to sleep
2017-12-14 09:33:38.925463 [DEBUG] sofia.c:7084 Channel sofia/external/XYZXYZXYZSD entering state [calling][0]
2017-12-14 09:33:38.925463 [DEBUG] sofia.c:7084 Channel sofia/external/XYZXYZXYZSD entering state [terminated][503]
2017-12-14 09:33:38.925463 [NOTICE] sofia.c:8273 Hangup sofia/external/XYZXYZXYZSD [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_HANGUP (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XYZXYZXYZSD) Callstate Change DOWN -> HANGUP
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:852 (sofia/external/XYZXYZXYZSD) State HANGUP
2017-12-14 09:33:38.925463 [DEBUG] mod_sofia.c:438 Channel sofia/external/XYZXYZXYZSD hanging up, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:60 sofia/external/XYZXYZXYZSD Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:852 (sofia/external/XYZXYZXYZSD) State HANGUP going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:619 (sofia/external/XYZXYZXYZSD) State Change CS_HANGUP -> CS_REPORTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_REPORTING (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:938 (sofia/external/XYZXYZXYZSD) State REPORTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:174 sofia/external/XYZXYZXYZSD Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:938 (sofia/external/XYZXYZXYZSD) State REPORTING going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:610 (sofia/external/XYZXYZXYZSD) State Change CS_REPORTING -> CS_DESTROY
2017-12-14 09:33:38.925463 [DEBUG] switch_core_session.c:1665 Session 7253 (sofia/external/XYZXYZXYZSD) Locked, Waiting on external entities
2017-12-14 09:33:38.949553 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2017-12-14 09:33:38.949553 [NOTICE] switch_core_session.c:1683 Session 7253 (sofia/external/XYZXYZXYZSD) Ended
2017-12-14 09:33:38.949553 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/XYZXYZXYZSD [CS_DESTROY]
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:741 (sofia/external/XYZXYZXYZSD) Running State Change CS_DESTROY (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:751 (sofia/external/XYZXYZXYZSD) State DESTROY
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:343 sofia/external/XYZXYZXYZSD SOFIA DESTROY
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:181 sofia/external/XYZXYZXYZSD Standard DESTROY
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:751 (sofia/external/XYZXYZXYZSD) State DESTROY going to sleep
2017-12-14 09:33:38.949553 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.949553 [NOTICE] switch_core_state_machine.c:385 sofia/internal/100@xxx.xxx.xxx.yz has executed the last dialplan instruction, hanging up.
2017-12-14 09:33:38.949553 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/100@xxx.xxx.xxx.yz [CS_EXECUTE] [NORMAL_CLEARING]
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100@xxx.xxx.xxx.yz) State EXECUTE going to sleep
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_HANGUP (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@xxx.xxx.xxx.yz) Callstate Change RINGING -> HANGUP
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100@xxx.xxx.xxx.yz) State HANGUP
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:432 sofia/internal/100@xxx.xxx.xxx.yz Overriding SIP cause 480 with 503 from the other leg
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100@xxx.xxx.xxx.yz hanging up, cause: NORMAL_CLEARING
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 503
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100@xxx.xxx.xxx.yz Standard HANGUP, cause: NORMAL_CLEARING
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100@xxx.xxx.xxx.yz) State HANGUP going to sleep
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_HANGUP -> CS_REPORTING
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_REPORTING (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100@xxx.xxx.xxx.yz) State REPORTING
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100@xxx.xxx.xxx.yz Standard REPORTING, cause: NORMAL_CLEARING
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100@xxx.xxx.xxx.yz) State REPORTING going to sleep
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_REPORTING -> CS_DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_session.c:1665 Session 7252 (sofia/internal/100@xxx.xxx.xxx.yz) Locked, Waiting on external entities
2017-12-14 09:33:39.025490 [NOTICE] switch_core_session.c:1683 Session 7252 (sofia/internal/100@xxx.xxx.xxx.yz) Ended
2017-12-14 09:33:39.025490 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/100@xxx.xxx.xxx.yz [CS_DESTROY]
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_DESTROY (Cur 0 Tot 7253)
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100@xxx.xxx.xxx.yz) State DESTROY
2017-12-14 09:33:39.025490 [DEBUG] mod_sofia.c:343 sofia/internal/100@xxx.xxx.xxx.yz SOFIA DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100@xxx.xxx.xxx.yz Standard DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100@xxx.xxx.xxx.yz) State DESTROY going to sleep
i have install new fusionPBX i m trying to send calls to PLIVO, but call HANGUP with NORMAL_CLEARING
billow are the logs ...
.
.
.
.
.
.
2017-12-14 09:33:38.605560 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/100@xxx.xxx.xxx.yz) State NEW
2017-12-14 09:33:38.605560 [DEBUG] sofia.c:2334 detaching session e61b48dd-834b-401b-b86b-723c529dd4a4
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:2442 Re-attaching to session e61b48dd-834b-401b-b86b-723c529dd4a4
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:9873 sofia/internal/100@xxx.xxx.xxx.yz receiving invite from 124.253.8.219:10000 version: 1.6.19 -36-7a77e0b 64bit
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:10044 IP 124.253.8.219 Rejected by acl "domains". Falling back to Digest auth.
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:11168 Setting NAT mode based on via received
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7084 Channel sofia/internal/100@xxx.xxx.xxx.yz entering state [received][100]
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=Z 0 0 IN IP4 192.168.1.14
s=Z
c=IN IP4 192.168.1.14
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[G722:9:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[GSM:3:8000:20:13200:1]
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/100@xxx.xxx.xxx.yz GSM/8000 20 ms 160 samples 13200 bits 1 channels
2017-12-14 09:33:38.885494 [DEBUG] switch_core_codec.c:111 sofia/internal/100@xxx.xxx.xxx.yz Original read codec set to GSM:3
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2017-12-14 09:33:38.885494 [DEBUG] switch_core_media.c:4767 sofia/internal/100@xxx.xxx.xxx.yz Set 2833 dtmf send payload to 101 recv payload to 101
2017-12-14 09:33:38.885494 [DEBUG] sofia.c:7507 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_NEW -> CS_INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_INIT (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100@xxx.xxx.xxx.yz) State INIT
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:90 sofia/internal/100@xxx.xxx.xxx.yz SOFIA INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100@xxx.xxx.xxx.yz Standard INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_INIT -> CS_ROUTING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100@xxx.xxx.xxx.yz) State INIT going to sleep
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_ROUTING (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_channel.c:2249 (sofia/internal/100@xxx.xxx.xxx.yz) Callstate Change DOWN -> RINGING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100@xxx.xxx.xxx.yz) State ROUTING
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:143 sofia/internal/100@xxx.xxx.xxx.yz SOFIA ROUTING
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:236 sofia/internal/100@xxx.xxx.xxx.yz Standard ROUTING
2017-12-14 09:33:38.885494 [INFO] mod_dialplan_xml.c:637 Processing 100 <100>->XYZXYZXYZSD in context public
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz parsing [public->57720099005466363.zt.plivo.com.d11] continue=false
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Regex (PASS) [57720099005466363.zt.plivo.com.d11] destination_number(XYZXYZXYZSD) =~ /^(\d{11})$/ break=on-false
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(call_direction=inbound)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [call_direction]=[inbound]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(domain_uuid=858c5728-acb4-4004-8f43-15c090d1bb04) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(domain_uuid=858c5728-acb4-4004-8f43-15c090d1bb04)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [domain_uuid]=[858c5728-acb4-4004-8f43-15c090d1bb04]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(domain_name=xxx.xxx.xxx.yz) INLINE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(domain_name=xxx.xxx.xxx.yz)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [domain_name]=[xxx.xxx.xxx.yz]
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(call_direction=outbound)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action unset(call_timeout)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(inherit_codec=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(ignore_display_updates=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(callee_id_number=XYZXYZXYZSD)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action set(continue_on_fail=true)
Dialplan: sofia/internal/100@xxx.xxx.xxx.yz Action bridge(sofia/gateway/c7dd0b64-8ff0-46f8-9bbc-8be282ba1073/XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_ROUTING -> CS_EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100@xxx.xxx.xxx.yz) State ROUTING going to sleep
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_EXECUTE (Cur 1 Tot 7252)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100@xxx.xxx.xxx.yz) State EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:198 sofia/internal/100@xxx.xxx.xxx.yz SOFIA EXECUTE
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:328 sofia/internal/100@xxx.xxx.xxx.yz Standard EXECUTE
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(sip_h_X-accountcode=xxx.xxx.xxx.yz)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [sip_h_X-accountcode]=[xxx.xxx.xxx.yz]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(call_direction=outbound)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [call_direction]=[outbound]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz unset(call_timeout)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(hangup_after_bridge=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [hangup_after_bridge]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(effective_caller_id_name=)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(effective_caller_id_number=2123727255)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [effective_caller_id_number]=[2123727255]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(inherit_codec=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [inherit_codec]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(ignore_display_updates=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [ignore_display_updates]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(callee_id_number=XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [callee_id_number]=[XYZXYZXYZSD]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz set(continue_on_fail=true)
2017-12-14 09:33:38.885494 [DEBUG] mod_dptools.c:1548 SET sofia/internal/100@xxx.xxx.xxx.yz [continue_on_fail]=[true]
EXECUTE sofia/internal/100@xxx.xxx.xxx.yz bridge(sofia/gateway/c7dd0b64-8ff0-46f8-9bbc-8be282ba1073/XYZXYZXYZSD)
2017-12-14 09:33:38.885494 [DEBUG] switch_channel.c:1250 sofia/internal/100@xxx.xxx.xxx.yz EXPORTING[export_vars] [domain_name]=[xxx.xxx.xxx.yz] to event
2017-12-14 09:33:38.885494 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-12-14 09:33:38.885494 [NOTICE] switch_channel.c:1104 New Channel sofia/external/XYZXYZXYZSD [ceb04666-775e-4949-a92a-1b6e4fb48a70]
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:4819 (sofia/external/XYZXYZXYZSD) State Change CS_NEW -> CS_INIT
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_INIT (Cur 2 Tot 7253)
2017-12-14 09:33:38.885494 [DEBUG] switch_core_state_machine.c:627 (sofia/external/XYZXYZXYZSD) State INIT
2017-12-14 09:33:38.885494 [DEBUG] mod_sofia.c:90 sofia/external/XYZXYZXYZSD SOFIA INIT
2017-12-14 09:33:38.925463 [DEBUG] switch_core_media.c:9710 sofia/external/XYZXYZXYZSD Patched SDP
v=0
o=Z 0 0 IN IP4 192.168.1.14
s=Z
c=IN IP4 192.168.1.14
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
+++
v=0
o=FreeSWITCH 2632333171 2632333172 IN IP4 xxx.xxx.xxx.yz
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.yz
t=0 0
m=audio 28974 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.925463 [DEBUG] sofia_glue.c:1295 sofia/external/XYZXYZXYZSD sending invite version: 1.6.19 -36-7a77e0b 64bit
Local SDP:
v=0
o=FreeSWITCH 2632333171 2632333172 IN IP4 xxx.xxx.xxx.yz
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.yz
t=0 0
m=audio 28974 RTP/AVP 3 110 8 0 97 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:40 sofia/external/XYZXYZXYZSD Standard INIT
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XYZXYZXYZSD) State Change CS_INIT -> CS_ROUTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:627 (sofia/external/XYZXYZXYZSD) State INIT going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_ROUTING (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:643 (sofia/external/XYZXYZXYZSD) State ROUTING
2017-12-14 09:33:38.925463 [DEBUG] mod_sofia.c:143 sofia/external/XYZXYZXYZSD SOFIA ROUTING
2017-12-14 09:33:38.925463 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XYZXYZXYZSD) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:643 (sofia/external/XYZXYZXYZSD) State ROUTING going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:662 (sofia/external/XYZXYZXYZSD) State CONSUME_MEDIA
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:662 (sofia/external/XYZXYZXYZSD) State CONSUME_MEDIA going to sleep
2017-12-14 09:33:38.925463 [DEBUG] sofia.c:7084 Channel sofia/external/XYZXYZXYZSD entering state [calling][0]
2017-12-14 09:33:38.925463 [DEBUG] sofia.c:7084 Channel sofia/external/XYZXYZXYZSD entering state [terminated][503]
2017-12-14 09:33:38.925463 [NOTICE] sofia.c:8273 Hangup sofia/external/XYZXYZXYZSD [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_HANGUP (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XYZXYZXYZSD) Callstate Change DOWN -> HANGUP
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:852 (sofia/external/XYZXYZXYZSD) State HANGUP
2017-12-14 09:33:38.925463 [DEBUG] mod_sofia.c:438 Channel sofia/external/XYZXYZXYZSD hanging up, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:60 sofia/external/XYZXYZXYZSD Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:852 (sofia/external/XYZXYZXYZSD) State HANGUP going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:619 (sofia/external/XYZXYZXYZSD) State Change CS_HANGUP -> CS_REPORTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:584 (sofia/external/XYZXYZXYZSD) Running State Change CS_REPORTING (Cur 2 Tot 7253)
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:938 (sofia/external/XYZXYZXYZSD) State REPORTING
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:174 sofia/external/XYZXYZXYZSD Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:938 (sofia/external/XYZXYZXYZSD) State REPORTING going to sleep
2017-12-14 09:33:38.925463 [DEBUG] switch_core_state_machine.c:610 (sofia/external/XYZXYZXYZSD) State Change CS_REPORTING -> CS_DESTROY
2017-12-14 09:33:38.925463 [DEBUG] switch_core_session.c:1665 Session 7253 (sofia/external/XYZXYZXYZSD) Locked, Waiting on external entities
2017-12-14 09:33:38.949553 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2017-12-14 09:33:38.949553 [NOTICE] switch_core_session.c:1683 Session 7253 (sofia/external/XYZXYZXYZSD) Ended
2017-12-14 09:33:38.949553 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/XYZXYZXYZSD [CS_DESTROY]
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:741 (sofia/external/XYZXYZXYZSD) Running State Change CS_DESTROY (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:751 (sofia/external/XYZXYZXYZSD) State DESTROY
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:343 sofia/external/XYZXYZXYZSD SOFIA DESTROY
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:181 sofia/external/XYZXYZXYZSD Standard DESTROY
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:751 (sofia/external/XYZXYZXYZSD) State DESTROY going to sleep
2017-12-14 09:33:38.949553 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
2017-12-14 09:33:38.949553 [NOTICE] switch_core_state_machine.c:385 sofia/internal/100@xxx.xxx.xxx.yz has executed the last dialplan instruction, hanging up.
2017-12-14 09:33:38.949553 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/100@xxx.xxx.xxx.yz [CS_EXECUTE] [NORMAL_CLEARING]
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100@xxx.xxx.xxx.yz) State EXECUTE going to sleep
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_HANGUP (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@xxx.xxx.xxx.yz) Callstate Change RINGING -> HANGUP
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100@xxx.xxx.xxx.yz) State HANGUP
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:432 sofia/internal/100@xxx.xxx.xxx.yz Overriding SIP cause 480 with 503 from the other leg
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100@xxx.xxx.xxx.yz hanging up, cause: NORMAL_CLEARING
2017-12-14 09:33:38.949553 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 503
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100@xxx.xxx.xxx.yz Standard HANGUP, cause: NORMAL_CLEARING
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100@xxx.xxx.xxx.yz) State HANGUP going to sleep
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_HANGUP -> CS_REPORTING
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_REPORTING (Cur 1 Tot 7253)
2017-12-14 09:33:38.949553 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100@xxx.xxx.xxx.yz) State REPORTING
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100@xxx.xxx.xxx.yz Standard REPORTING, cause: NORMAL_CLEARING
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100@xxx.xxx.xxx.yz) State REPORTING going to sleep
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100@xxx.xxx.xxx.yz) State Change CS_REPORTING -> CS_DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_session.c:1665 Session 7252 (sofia/internal/100@xxx.xxx.xxx.yz) Locked, Waiting on external entities
2017-12-14 09:33:39.025490 [NOTICE] switch_core_session.c:1683 Session 7252 (sofia/internal/100@xxx.xxx.xxx.yz) Ended
2017-12-14 09:33:39.025490 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/100@xxx.xxx.xxx.yz [CS_DESTROY]
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100@xxx.xxx.xxx.yz) Running State Change CS_DESTROY (Cur 0 Tot 7253)
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100@xxx.xxx.xxx.yz) State DESTROY
2017-12-14 09:33:39.025490 [DEBUG] mod_sofia.c:343 sofia/internal/100@xxx.xxx.xxx.yz SOFIA DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100@xxx.xxx.xxx.yz Standard DESTROY
2017-12-14 09:33:39.025490 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100@xxx.xxx.xxx.yz) State DESTROY going to sleep