span style="color: cornflowerblue; font-weight: bold;"> 2016-08-02 02:28:14.710556 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2600@192.168.0.137 [c3d65838-5858-11e6-b12a-adaf8bea1064]
2016-08-02 02:28:14.710556 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_NEW
2016-08-02 02:28:14.710556 [DEBUG] sofia.c:9518 sofia/internal/2600@192.168.0.137 receiving invite from 192.168.0.12:60409 version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
2016-08-02 02:28:14.710556 [DEBUG] sofia.c:9685 IP 192.168.0.12 Rejected by acl "domains". Falling back to Digest auth.
2016-08-02 02:28:14.710556 [WARNING] sofia_reg.c:1787 SIP auth challenge (INVITE) on sofia profile 'internal' for [2001@192.168.0.137] from ip 192.168.0.12
2016-08-02 02:28:14.710556 [DEBUG] switch_core_state_machine.c:562 (sofia/internal/2600@192.168.0.137) State NEW
2016-08-02 02:28:14.710556 [DEBUG] sofia.c:2248 detaching session c3d65838-5858-11e6-b12a-adaf8bea1064
2016-08-02 02:28:14.890175 [DEBUG] sofia.c:2356 Re-attaching to session c3d65838-5858-11e6-b12a-adaf8bea1064
2016-08-02 02:28:14.890175 [DEBUG] sofia.c:9518 sofia/internal/2600@192.168.0.137 receiving invite from 192.168.0.12:60409 version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
2016-08-02 02:28:14.890175 [DEBUG] sofia.c:9685 IP 192.168.0.12 Rejected by acl "domains". Falling back to Digest auth.
2016-08-02 02:28:14.910179 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [received][100]
2016-08-02 02:28:14.910179 [DEBUG] sofia.c:6947 Remote SDP:
v=0
o=- 1470104894 1470104894 IN IP4 192.168.0.12
s=Polycom IP Phone
c=IN IP4 192.168.0.12
t=0 0
a=sendrecv
m=audio 2224 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000
2016-08-02 02:28:14.910179 [DEBUG] sofia.c:7315 (sofia/internal/2600@192.168.0.137) State Change CS_NEW -> CS_INIT
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_INIT
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.137) State INIT
2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:90 sofia/internal/2600@192.168.0.137 SOFIA INIT
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2600@192.168.0.137 Standard INIT
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2600@192.168.0.137) State Change CS_INIT -> CS_ROUTING
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.137) State INIT going to sleep
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_ROUTING
2016-08-02 02:28:14.910179 [DEBUG] switch_channel.c:2249 (sofia/internal/2600@192.168.0.137) Callstate Change DOWN -> RINGING
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.137) State ROUTING
2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:143 sofia/internal/2600@192.168.0.137 SOFIA ROUTING
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:236 sofia/internal/2600@192.168.0.137 Standard ROUTING
2016-08-02 02:28:14.910179 [INFO] mod_dialplan_xml.c:637 Processing jungle boogie <2600>->2001 in context default
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->unloop] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/2600@192.168.0.137 Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/2600@192.168.0.137 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global-intercept] destination_number(2001) =~ /^886$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [group-intercept] destination_number(2001) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [intercept-ext] destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->redial] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [redial] destination_number(2001) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->global] continue=true
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${default_password}(lfklsnfknjfhfh843^$(0&^fsjklaCoI4_3944/*) =~ /^1234$/ break=never
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HM
AC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 1470104894 1470104894 IN IP4 192.168.0.12
s=Polycom IP Phone
c=IN IP4 192.168.0.12
t=0 0
a=sendrecv
m=audio 2224 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/2600@192.168.0.137 Absolute Condition [global]
Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/2600@192.168.0.137 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [snom-demo-2] destination_number(2001) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [snom-demo-1] destination_number(2001) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false [170/1813]
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^779$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call_return] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call_return] destination_number(2001) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->del-group] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [del-group] destination_number(2001) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->add-group] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [add-group] destination_number(2001) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call-group-simo] destination_number(2001) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call-group-order] destination_number(2001) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [extension-intercom] destination_number(2001) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [Local_Extension] destination_number(2001) =~ /^(26[01][0-9]|phone|mobile)$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [Local_Extension_Skinny] destination_number(2001) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group_dial_sales] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [group_dial_sales] destination_number(2001) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group_dial_support] continue=false
Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [group_dial_support] destination_number(2001) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/2600@192.168.0.137 Action set(call_timeout=20)
Dialplan: sofia/internal/2600@192.168.0.137 Action set(continue_on_fail=true)
Dialplan: sofia/internal/2600@192.168.0.137 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/2600@192.168.0.137 Action bridge(group/support@${domain_name})
Dialplan: sofia/internal/2600@192.168.0.137 Action answer()
Dialplan: sofia/internal/2600@192.168.0.137 Action sleep(2000)
Dialplan: sofia/internal/2600@192.168.0.137 Action voicemail(default 2600)
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/2600@192.168.0.137) State Change CS_ROUTING -> CS_EXECUTE
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.137) State ROUTING going to sleep
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_EXECUTE
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/2600@192.168.0.137) State EXECUTE
2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:198 sofia/internal/2600@192.168.0.137 SOFIA EXECUTE
2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:328 sofia/internal/2600@192.168.0.137 Standard EXECUTE
EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-spymap/2600/c3d65838-5858-11e6-b12a-adaf8bea1064)
EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-last_dial/2600/2001)
EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-last_dial/global/c3d65838-5858-11e6-b12a-adaf8bea1064) [132/1813]
EXECUTE sofia/internal/2600@192.168.0.137 export(RFC2822_DATE=Tue, 02 Aug 2016 02:28:14 +0000)
2016-08-02 02:28:14.910179 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000]
EXECUTE sofia/internal/2600@192.168.0.137 set(call_timeout=20)
2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [call_timeout]=[20]
EXECUTE sofia/internal/2600@192.168.0.137 set(continue_on_fail=true)
2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [continue_on_fail]=[true]
EXECUTE sofia/internal/2600@192.168.0.137 set(hangup_after_bridge=true)
2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/2600@192.168.0.137 bridge(group/support@192.168.0.137)
2016-08-02 02:28:14.930226 [DEBUG] switch_channel.c:1250 sofia/internal/2600@192.168.0.137 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000] to event
2016-08-02 02:28:14.930226 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables
2016-08-02 02:28:14.950217 [DEBUG] switch_channel.c:1250 sofia/internal/2600@192.168.0.137 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000] to event
2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables
2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
2016-08-02 02:28:14.950217 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2600@192.168.0.12 [c3f965da-5858-11e6-b13b-adaf8bea1064]
2016-08-02 02:28:14.950217 [DEBUG] mod_sofia.c:4754 (sofia/internal/2600@192.168.0.12) State Change CS_NEW -> CS_INIT
2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
2016-08-02 02:28:14.950217 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_INIT
2016-08-02 02:28:14.950217 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.12) State INIT
2016-08-02 02:28:14.970210 [DEBUG] mod_sofia.c:90 sofia/internal/2600@192.168.0.12 SOFIA INIT
2016-08-02 02:28:14.970210 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2016-08-02 02:28:14.970210 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
2016-08-02 02:28:14.970210 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2016-08-02 02:28:14.970210 [DEBUG] sofia_glue.c:1249 sofia/internal/2600@192.168.0.12 sending invite version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
Local SDP:
v=0
o=FreeSWITCH 1470081874 1470081875 IN IP4 192.168.0.137
s=FreeSWITCH
c=IN IP4 192.168.0.137
t=0 0
m=audio 23020 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2600@192.168.0.12 Standard INIT
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2600@192.168.0.12) State Change CS_INIT -> CS_ROUTING
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.12) State INIT going to sleep
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_ROUTING
2016-08-02 02:28:14.970210 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.12 entering state [calling][0]
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.12) State ROUTING
2016-08-02 02:28:14.970210 [DEBUG] mod_sofia.c:143 sofia/internal/2600@192.168.0.12 SOFIA ROUTING
2016-08-02 02:28:14.970210 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/2600@192.168.0.12) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.12) State ROUTING going to sleep
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_CONSUME_MEDIA
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA
2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA going to sleep
2016-08-02 02:28:15.030162 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.12 entering state [terminated][486]
2016-08-02 02:28:15.030162 [NOTICE] sofia.c:8023 Hangup sofia/internal/2600@192.168.0.12 [CS_CONSUME_MEDIA] [USER_BUSY]
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_HANGUP
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2600@192.168.0.12) Callstate Change DOWN -> HANGUP
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.12) State HANGUP
2016-08-02 02:28:15.030162 [DEBUG] mod_sofia.c:438 Channel sofia/internal/2600@192.168.0.12 hanging up, cause: USER_BUSY
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2600@192.168.0.12 Standard HANGUP, cause: USER_BUSY
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.12) State HANGUP going to sleep
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2600@192.168.0.12) State Change CS_HANGUP -> CS_REPORTING
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_REPORTING
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.12) State REPORTING
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2600@192.168.0.12 Standard REPORTING, cause: USER_BUSY
2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.12) State REPORTING going to sleep
2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2600@192.168.0.12) State Change CS_REPORTING -> CS_DESTROY
2016-08-02 02:28:15.050206 [DEBUG] switch_core_session.c:1647 Session 83 (sofia/internal/2600@192.168.0.12) Locked, Waiting on external entities
2016-08-02 02:28:15.050206 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 17 [USER_BUSY]
2016-08-02 02:28:15.050206 [NOTICE] switch_core_session.c:1665 Session 83 (sofia/internal/2600@192.168.0.12) Ended
2016-08-02 02:28:15.050206 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/2600@192.168.0.12 [CS_DESTROY]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2600@192.168.0.12) Running State Change CS_DESTROY
2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.12) State DESTROY
2016-08-02 02:28:15.050206 [DEBUG] mod_sofia.c:343 sofia/internal/2600@192.168.0.12 SOFIA DESTROY
2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2600@192.168.0.12 Standard DESTROY
2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.12) State DESTROY going to sleep [56/1813]
2016-08-02 02:28:15.050206 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [group] cause: [USER_BUSY]
2016-08-02 02:28:15.050206 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 17 [USER_BUSY]
2016-08-02 02:28:15.050206 [INFO] mod_dptools.c:3401 Originate Failed. Cause: USER_BUSY
EXECUTE sofia/internal/2600@192.168.0.137 answer()
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[opus:116:48000:20:0:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4227 Set telephone-event payload to 127@8000
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:3018 Set Codec sofia/internal/2600@192.168.0.137 G722/8000 20 ms 160 samples 64000 bits 1 channels
2016-08-02 02:28:15.050206 [DEBUG] switch_core_codec.c:111 sofia/internal/2600@192.168.0.137 Original read codec set to G722:9
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4580 Set telephone-event payload to 127@8000
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4639 sofia/internal/2600@192.168.0.137 Set 2833 dtmf send payload to 127 recv payload to 127
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6465 AUDIO RTP [sofia/internal/2600@192.168.0.137] 192.168.0.137 port 29450 -> 192.168.0.12 port 2224 codec: 9 ms: 20
2016-08-02 02:28:15.050206 [DEBUG] switch_rtp.c:3833 Starting timer [soft] 160 bytes per 20ms
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6764 sofia/internal/2600@192.168.0.137 Set 2833 dtmf send payload to 127
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6771 sofia/internal/2600@192.168.0.137 Set 2833 dtmf receive payload to 127
2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6794 sofia/internal/2600@192.168.0.137 Set rtp dtmf delay to 40
2016-08-02 02:28:15.050206 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/2600@192.168.0.137!
2016-08-02 02:28:15.070584 [DEBUG] switch_channel.c:3471 (sofia/internal/2600@192.168.0.137) Callstate Change RINGING -> EARLY
2016-08-02 02:28:15.070584 [DEBUG] mod_sofia.c:822 Local SDP sofia/internal/2600@192.168.0.137:
v=0
o=FreeSWITCH 1470075445 1470075446 IN IP4 192.168.0.137
s=FreeSWITCH
c=IN IP4 192.168.0.137
t=0 0
m=audio 29450 RTP/AVP 9 127
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=sendrecv
2016-08-02 02:28:15.070584 [NOTICE] mod_dptools.c:1309 Channel [sofia/internal/2600@192.168.0.137] has been answered
2016-08-02 02:28:15.070584 [DEBUG] switch_channel.c:3770 (sofia/internal/2600@192.168.0.137) Callstate Change EARLY -> ACTIVE
2016-08-02 02:28:15.070584 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [completed][200]
EXECUTE sofia/internal/2600@192.168.0.137 sleep(2000)
2016-08-02 02:28:15.070584 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [ready][200]
2016-08-02 02:28:15.170161 [DEBUG] switch_rtp.c:6718 Correct audio ip/port confirmed.
EXECUTE sofia/internal/2600@192.168.0.137 voicemail(default 2600)
2016-08-02 02:28:17.230160 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2016-08-02 02:28:17.290184 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
2016-08-02 02:28:17.290184 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@16000hz 1 channels 20ms
2016-08-02 02:28:18.630198 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2016-08-02 02:28:18.750172 [DEBUG] switch_ivr_play_say.c:250 Handle say:[] (en:en)
2016-08-02 02:28:18.870206 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2016-08-02 02:28:18.950176 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-goodbye.wav] (en:en)
2016-08-02 02:28:18.950176 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@16000hz 1 channels 20ms
2016-08-02 02:28:19.090194 [NOTICE] sofia.c:988 Hangup sofia/internal/2600@192.168.0.137 [CS_EXECUTE] [NORMAL_CLEARING]
2016-08-02 02:28:19.090194 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-goodbye.wav
2016-08-02 02:28:19.090194 [DEBUG] switch_core_session.c:2797 sofia/internal/2600@192.168.0.137 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/2600@192.168.0.137) State EXECUTE going to sleep
2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_HANGUP
2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2600@192.168.0.137) Callstate Change ACTIVE -> HANGUP
2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.137) State HANGUP
2016-08-02 02:28:19.090194 [DEBUG] mod_sofia.c:432 sofia/internal/2600@192.168.0.137 Overriding SIP cause 480 with 486 from the other leg
2016-08-02 02:28:19.090194 [DEBUG] mod_sofia.c:438 Channel sofia/internal/2600@192.168.0.137 hanging up, cause: NORMAL_CLEARING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2600@192.168.0.137 Standard HANGUP, cause: NORMAL_CLEARING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.137) State HANGUP going to sleep
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2600@192.168.0.137) State Change CS_HANGUP -> CS_REPORTING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_REPORTING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.137) State REPORTING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2600@192.168.0.137 Standard REPORTING, cause: NORMAL_CLEARING
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.137) State REPORTING going to sleep
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2600@192.168.0.137) State Change CS_REPORTING -> CS_DESTROY
2016-08-02 02:28:19.110195 [DEBUG] switch_core_session.c:1647 Session 82 (sofia/internal/2600@192.168.0.137) Locked, Waiting on external entities
2016-08-02 02:28:19.110195 [NOTICE] switch_core_session.c:1665 Session 82 (sofia/internal/2600@192.168.0.137) Ended
2016-08-02 02:28:19.110195 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/2600@192.168.0.137 [CS_DESTROY]
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2600@192.168.0.137) Running State Change CS_DESTROY
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.137) State DESTROY
2016-08-02 02:28:19.110195 [DEBUG] mod_sofia.c:343 sofia/internal/2600@192.168.0.137 SOFIA DESTROY
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2600@192.168.0.137 Standard DESTROY
2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.137) State DESTROY going to sleep