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