2016-05-23 11:19:19.189827 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/3000@10.30.80.37 [1c895388-bdd1-4943-a5ae-823639c9d9b0]
2016-05-23 11:19:19.189827 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_NEW
2016-05-23 11:19:19.189827 [DEBUG] sofia.c:9376 sofia/internal/3000@10.30.80.37 receiving invite from 10.2.250.73:63361 version: 1.6.8 git 99de0ad 2016-05-05 15:38:32Z 64bit
2016-05-23 11:19:19.189827 [DEBUG] sofia.c:9543 IP 10.2.250.73 Rejected by acl "domains". Falling back to Digest auth.
2016-05-23 11:19:19.189827 [DEBUG] switch_core_state_machine.c:562 (sofia/internal/3000@10.30.80.37) State NEW
2016-05-23 11:19:19.189827 [DEBUG] sofia.c:2214 detaching session 1c895388-bdd1-4943-a5ae-823639c9d9b0
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:2322 Re-attaching to session 1c895388-bdd1-4943-a5ae-823639c9d9b0
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:9376 sofia/internal/3000@10.30.80.37 receiving invite from 10.2.250.73:63361 version: 1.6.8 git 99de0ad 2016-05-05 15:38:32Z 64bit
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:9543 IP 10.2.250.73 Rejected by acl "domains". Falling back to Digest auth.
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:6858 Channel sofia/internal/3000@10.30.80.37 entering state [received][100]
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:6868 Remote SDP:
v=0
o=- 13108472367345806 1 IN IP4 10.2.251.5
s=X-Lite release 4.9.3 stamp 79961
c=IN IP4 10.2.251.5
t=0 0
m=audio 54922 RTP/AVP 9 8 120 0 84 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:84 speex/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2016-05-23 11:19:19.229892 [DEBUG] sofia.c:7227 (sofia/internal/3000@10.30.80.37) State Change CS_NEW -> CS_INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/3000@10.30.80.37) State INIT
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:89 sofia/internal/3000@10.30.80.37 SOFIA INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:40 sofia/internal/3000@10.30.80.37 Standard INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/3000@10.30.80.37) State Change CS_INIT -> CS_ROUTING
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/3000@10.30.80.37) State INIT going to sleep
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_ROUTING
2016-05-23 11:19:19.229892 [DEBUG] switch_channel.c:2249 (sofia/internal/3000@10.30.80.37) Callstate Change DOWN -> RINGING
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/3000@10.30.80.37) State ROUTING
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:142 sofia/internal/3000@10.30.80.37 SOFIA ROUTING
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3000@10.30.80.37 Standard ROUTING
2016-05-23 11:19:19.229892 [INFO] mod_dialplan_xml.c:637 Processing 3000 <3000>->2000 in context default
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->unloop] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/3000@10.30.80.37 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->tod_3002_xfer] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [tod_3002_xfer] destination_number(2000) =~ /^3002$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [global-intercept] destination_number(2000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [group-intercept] destination_number(2000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [intercept-ext] destination_number(2000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->redial] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [redial] destination_number(2000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->global] continue=true
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [global] ${default_password}(1356) =~ /^1234$/ break=never
Dialplan: sofia/internal/3000@10.30.80.37 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_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 13108472367345806 1 IN IP4 10.2.251.5
s=X-Lite release 4.9.3 stamp 79961
c=IN IP4 10.2.251.5
t=0 0
m=audio 54922 RTP/AVP 9 8 120 0 84 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:84 speex/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/3000@10.30.80.37 Absolute Condition [global]
Dialplan: sofia/internal/3000@10.30.80.37 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/3000@10.30.80.37 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/3000@10.30.80.37 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/3000@10.30.80.37 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [snom-demo-2] destination_number(2000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [snom-demo-1] destination_number(2000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [eavesdrop] destination_number(2000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [eavesdrop] destination_number(2000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->call_return] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [call_return] destination_number(2000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->del-group] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [del-group] destination_number(2000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->add-group] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [add-group] destination_number(2000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [call-group-simo] destination_number(2000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [call-group-order] destination_number(2000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [extension-intercom] destination_number(2000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [Local_Extension] destination_number(2000) =~ /^(300[0-9])$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [Local_Extension_Skinny] destination_number(2000) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->operator] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [operator] destination_number(2000) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->vmain] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [vmain] destination_number(2000) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [sip_uri] destination_number(2000) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [nb_conferences] destination_number(2000) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->wb_conferences] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [wb_conferences] destination_number(2000) =~ /^(31\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->uwb_conferences] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [uwb_conferences] destination_number(2000) =~ /^(32\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [cdquality_conferences] destination_number(2000) =~ /^(33\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [cdquality_conferences] destination_number(2000) =~ /^(35\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(2000) =~ /^9(888|8888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [mad_boss_intercom] destination_number(2000) =~ /^0911$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [mad_boss_intercom] destination_number(2000) =~ /^0912$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->mad_boss] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [mad_boss] destination_number(2000) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ivr_demo] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ivr_demo] destination_number(2000) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->dynamic_conference] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [dynamic_conference] destination_number(2000) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [rtp_multicast_page] destination_number(2000) =~ /^pagegroup$|^7243$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->park] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [park] destination_number(2000) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->unpark] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [unpark] destination_number(2000) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->valet_park] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [valet_park] destination_number(2000) =~ /^(6000)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->valet_park] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [valet_park] destination_number(2000) =~ /^((?!6000)60\d{2})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->park] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [park] destination_number(2000) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->unpark] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [unpark] destination_number(2000) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->park] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [park] destination_number(2000) =~ /callpark/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->unpark] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [unpark] destination_number(2000) =~ /pickup/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->wait] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [wait] destination_number(2000) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->fax_receive] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [fax_receive] destination_number(2000) =~ /^9178$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->fax_transmit] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [fax_transmit] destination_number(2000) =~ /^9179$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ringback_180] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ringback_180] destination_number(2000) =~ /^9180$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ringback_183_uk_ring] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ringback_183_uk_ring] destination_number(2000) =~ /^9181$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ringback_183_music_ring] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ringback_183_music_ring] destination_number(2000) =~ /^9182$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ringback_post_answer_uk_ring] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(2000) =~ /^9183$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ringback_post_answer_music] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ringback_post_answer_music] destination_number(2000) =~ /^9184$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->ClueCon] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [ClueCon] destination_number(2000) =~ /^9191$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->show_info] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [show_info] destination_number(2000) =~ /^9192$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->video_record] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [video_record] destination_number(2000) =~ /^9193$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->video_playback] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [video_playback] destination_number(2000) =~ /^9194$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->delay_echo] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [delay_echo] destination_number(2000) =~ /^9195$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->echo] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [echo] destination_number(2000) =~ /^9196$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->milliwatt] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [milliwatt] destination_number(2000) =~ /^9197$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->tone_stream] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [tone_stream] destination_number(2000) =~ /^9198$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->zrtp_enrollement] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [zrtp_enrollement] destination_number(2000) =~ /^9787$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->hold_music] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [hold_music] destination_number(2000) =~ /^9664$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->laugh break] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [laugh break] destination_number(2000) =~ /^9386$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->101] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [101] destination_number(2000) =~ /^101$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->pizza_demo] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [pizza_demo] destination_number(2000) =~ /^(pizza|74992)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->Talking Clock Time] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [Talking Clock Time] destination_number(2000) =~ /^9170$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->Talking Clock Date] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [Talking Clock Date] destination_number(2000) =~ /^9171$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->Talking Clock Date and Time] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [Talking Clock Date and Time] destination_number(2000) =~ /^9172$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->local.example.com] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [local.example.com] ${toll_allow}(domestic,international,local) =~ /local/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [local.example.com] destination_number(2000) =~ /^(\d{7})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->domestic.example.com] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [domestic.example.com] ${toll_allow}(domestic,international,local) =~ /domestic/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [domestic.example.com] destination_number(2000) =~ /^(\d{11})$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->international.example.com] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [international.example.com] ${toll_allow}(domestic,international,local) =~ /international/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (FAIL) [international.example.com] destination_number(2000) =~ /^(011\d+)$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 parsing [default->DialToCharlotteFreeSwitch-TEST] continue=false
Dialplan: sofia/internal/3000@10.30.80.37 Regex (PASS) [DialToCharlotteFreeSwitch-TEST] destination_number(2000) =~ /^(20[01][0-9])$/ break=on-false
Dialplan: sofia/internal/3000@10.30.80.37 Action bridge(sofia/internal/2000@10.30.88.12)
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3000@10.30.80.37) State Change CS_ROUTING -> CS_EXECUTE
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/3000@10.30.80.37) State ROUTING going to sleep
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_EXECUTE
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/3000@10.30.80.37) State EXECUTE
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:197 sofia/internal/3000@10.30.80.37 SOFIA EXECUTE
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3000@10.30.80.37 Standard EXECUTE
EXECUTE sofia/internal/3000@10.30.80.37 hash(insert/10.30.80.37-spymap/3000/1c895388-bdd1-4943-a5ae-823639c9d9b0)
EXECUTE sofia/internal/3000@10.30.80.37 hash(insert/10.30.80.37-last_dial/3000/2000)
EXECUTE sofia/internal/3000@10.30.80.37 hash(insert/10.30.80.37-last_dial/global/1c895388-bdd1-4943-a5ae-823639c9d9b0)
EXECUTE sofia/internal/3000@10.30.80.37 export(RFC2822_DATE=Mon, 23 May 2016 11:19:19 +0100)
2016-05-23 11:19:19.229892 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 23 May 2016 11:19:19 +0100]
EXECUTE sofia/internal/3000@10.30.80.37 bridge(sofia/internal/2000@10.30.88.12)
2016-05-23 11:19:19.229892 [DEBUG] switch_channel.c:1250 sofia/internal/3000@10.30.80.37 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 23 May 2016 11:19:19 +0100] to event
2016-05-23 11:19:19.229892 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables
2016-05-23 11:19:19.229892 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2000@10.30.88.12 [465dfcac-6356-43cb-88ca-71f2aacfbfe6]
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:4813 (sofia/internal/2000@10.30.88.12) State Change CS_NEW -> CS_INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2000@10.30.88.12) State INIT
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:89 sofia/internal/2000@10.30.88.12 SOFIA INIT
2016-05-23 11:19:19.229892 [DEBUG] sofia_glue.c:1257 sofia/internal/2000@10.30.88.12 sending invite version: 1.6.8 git 99de0ad 2016-05-05 15:38:32Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1463979859 1463979860 IN IP4 10.30.80.37
s=FreeSWITCH
c=IN IP4 10.30.80.37
t=0 0
m=audio 18900 RTP/AVP 9 8 120 0 101 102
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:102 telephone-event/48000
a=fmtp:102 0-16
a=ptime:20
a=sendrecv

2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2000@10.30.88.12 Standard INIT
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2000@10.30.88.12) State Change CS_INIT -> CS_ROUTING
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2000@10.30.88.12) State INIT going to sleep
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_ROUTING
2016-05-23 11:19:19.229892 [DEBUG] sofia.c:6858 Channel sofia/internal/2000@10.30.88.12 entering state [calling][0]
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2000@10.30.88.12) State ROUTING
2016-05-23 11:19:19.229892 [DEBUG] mod_sofia.c:142 sofia/internal/2000@10.30.88.12 SOFIA ROUTING
2016-05-23 11:19:19.229892 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/2000@10.30.88.12) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2000@10.30.88.12) State ROUTING going to sleep
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_CONSUME_MEDIA
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2000@10.30.88.12) State CONSUME_MEDIA
2016-05-23 11:19:19.229892 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2000@10.30.88.12) State CONSUME_MEDIA going to sleep
2016-05-23 11:19:29.769887 [INFO] sofia.c:1255 sofia/internal/2000@10.30.88.12 Update Callee ID to "2000" <sip:2000@10.30.88.12>
2016-05-23 11:19:29.769887 [DEBUG] sofia.c:6858 Channel sofia/internal/2000@10.30.88.12 entering state [proceeding][183]
2016-05-23 11:19:29.769887 [DEBUG] sofia.c:6868 Remote SDP:
v=0
o=FreeSWITCH 1463977384 1463977385 IN IP4 10.30.88.12
s=FreeSWITCH
c=IN IP4 10.30.88.12
t=0 0
m=audio 21210 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:2]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:3090 Set Codec sofia/internal/2000@10.30.88.12 G722/8000 20 ms 160 samples 64000 bits 1 channels
2016-05-23 11:19:29.769887 [DEBUG] switch_core_codec.c:111 sofia/internal/2000@10.30.88.12 Original read codec set to G722:9
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4681 sofia/internal/2000@10.30.88.12 Set 2833 dtmf send payload to 101 recv payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/internal/2000@10.30.88.12] 10.30.80.37 port 18900 -> 10.30.88.12 port 21210 codec: 9 ms: 20
2016-05-23 11:19:29.769887 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6763 sofia/internal/2000@10.30.88.12 Set 2833 dtmf send payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6770 sofia/internal/2000@10.30.88.12 Set 2833 dtmf receive payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6793 sofia/internal/2000@10.30.88.12 Set rtp dtmf delay to 40
2016-05-23 11:19:29.769887 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/2000@10.30.88.12!
2016-05-23 11:19:29.769887 [DEBUG] switch_channel.c:3471 (sofia/internal/2000@10.30.88.12) Callstate Change DOWN -> EARLY
2016-05-23 11:19:29.769887 [INFO] switch_ivr_originate.c:3556 Sending early media
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [opus:120:48000:20:0:1]/[opus:116:48000:20:0:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [opus:120:48000:20:0:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [speex:84:16000:20:0:1]/[opus:116:48000:20:0:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [speex:84:16000:20:0:1]/[G722:9:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [speex:84:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [speex:84:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:3090 Set Codec sofia/internal/3000@10.30.80.37 G722/8000 20 ms 160 samples 64000 bits 1 channels
2016-05-23 11:19:29.769887 [DEBUG] switch_core_codec.c:111 sofia/internal/3000@10.30.80.37 Original read codec set to G722:9
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:4681 sofia/internal/3000@10.30.80.37 Set 2833 dtmf send payload to 101 recv payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/internal/3000@10.30.80.37] 10.30.80.37 port 32720 -> 10.2.251.5 port 54922 codec: 9 ms: 20
2016-05-23 11:19:29.769887 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6763 sofia/internal/3000@10.30.80.37 Set 2833 dtmf send payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6770 sofia/internal/3000@10.30.80.37 Set 2833 dtmf receive payload to 101
2016-05-23 11:19:29.769887 [DEBUG] switch_core_media.c:6793 sofia/internal/3000@10.30.80.37 Set rtp dtmf delay to 40
2016-05-23 11:19:29.769887 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/3000@10.30.80.37!
2016-05-23 11:19:29.769887 [DEBUG] switch_channel.c:3471 (sofia/internal/3000@10.30.80.37) Callstate Change RINGING -> EARLY
2016-05-23 11:19:29.769887 [DEBUG] mod_sofia.c:2367 Ring SDP:
v=0
o=FreeSWITCH 1463966049 1463966050 IN IP4 10.30.80.37
s=FreeSWITCH
c=IN IP4 10.30.80.37
t=0 0
m=audio 32720 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2016-05-23 11:19:29.769887 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/2000@10.30.88.12]
2016-05-23 11:19:29.769887 [DEBUG] sofia.c:6858 Channel sofia/internal/3000@10.30.80.37 entering state [early][183]
2016-05-23 11:19:29.769887 [DEBUG] switch_ivr_bridge.c:1594 (sofia/internal/2000@10.30.88.12) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2016-05-23 11:19:29.769887 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_EXCHANGE_MEDIA
2016-05-23 11:19:29.769887 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/2000@10.30.88.12) State EXCHANGE_MEDIA
2016-05-23 11:19:29.769887 [DEBUG] mod_sofia.c:628 SOFIA EXCHANGE_MEDIA
2016-05-23 11:19:29.849882 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed.
2016-05-23 11:19:30.169840 [INFO] switch_rtp.c:6669 Auto Changing audio port from 10.2.251.5:54922 to 10.2.250.73:54922
2016-05-23 11:19:31.009886 [DEBUG] sofia.c:6858 Channel sofia/internal/3000@10.30.80.37 entering state [terminated][487]
2016-05-23 11:19:31.009886 [NOTICE] sofia.c:7881 Hangup sofia/internal/3000@10.30.80.37 [CS_EXECUTE] [ORIGINATOR_CANCEL]
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:707 sofia/internal/3000@10.30.80.37 ending bridge by request from read function
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/internal/3000@10.30.80.37]
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:701 sofia/internal/3000@10.30.80.37 ending bridge by request from write function
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/internal/2000@10.30.88.12]
2016-05-23 11:19:31.009886 [NOTICE] switch_ivr_bridge.c:882 Hangup sofia/internal/2000@10.30.88.12 [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/2000@10.30.88.12) State EXCHANGE_MEDIA going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_HANGUP
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:1692 sofia/internal/2000@10.30.88.12 skip receive message [UNBRIDGE] (channel is hungup already)
2016-05-23 11:19:31.009886 [DEBUG] switch_ivr_bridge.c:1695 sofia/internal/3000@10.30.80.37 skip receive message [UNBRIDGE] (channel is hungup already)
2016-05-23 11:19:31.009886 [DEBUG] switch_core_session.c:2796 sofia/internal/3000@10.30.80.37 skip receive message [PHONE_EVENT] (channel is hungup already)
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/3000@10.30.80.37) State EXECUTE going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_HANGUP
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/3000@10.30.80.37) Callstate Change EARLY -> HANGUP
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2000@10.30.88.12) Callstate Change EARLY -> HANGUP
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/3000@10.30.80.37) State HANGUP
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:437 Channel sofia/internal/3000@10.30.80.37 hanging up, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2000@10.30.88.12) State HANGUP
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:431 sofia/internal/2000@10.30.88.12 Overriding SIP cause 487 with 487 from the other leg
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:437 Channel sofia/internal/2000@10.30.88.12 hanging up, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:60 sofia/internal/3000@10.30.80.37 Standard HANGUP, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/3000@10.30.80.37) State HANGUP going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/3000@10.30.80.37) State Change CS_HANGUP -> CS_REPORTING
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/3000@10.30.80.37) Running State Change CS_REPORTING
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/3000@10.30.80.37) State REPORTING
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:501 Sending CANCEL to sofia/internal/2000@10.30.88.12
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:174 sofia/internal/3000@10.30.80.37 Standard REPORTING, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/3000@10.30.80.37) State REPORTING going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/3000@10.30.80.37) State Change CS_REPORTING -> CS_DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_session.c:1646 Session 166 (sofia/internal/3000@10.30.80.37) Locked, Waiting on external entities
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2000@10.30.88.12 Standard HANGUP, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2000@10.30.88.12) State HANGUP going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2000@10.30.88.12) State Change CS_HANGUP -> CS_REPORTING
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2000@10.30.88.12) Running State Change CS_REPORTING
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2000@10.30.88.12) State REPORTING
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2000@10.30.88.12 Standard REPORTING, cause: ORIGINATOR_CANCEL
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2000@10.30.88.12) State REPORTING going to sleep
2016-05-23 11:19:31.009886 [NOTICE] switch_core_session.c:1664 Session 166 (sofia/internal/3000@10.30.80.37) Ended
2016-05-23 11:19:31.009886 [NOTICE] switch_core_session.c:1668 Close Channel sofia/internal/3000@10.30.80.37 [CS_DESTROY]
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/3000@10.30.80.37) Running State Change CS_DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/3000@10.30.80.37) State DESTROY
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:342 sofia/internal/3000@10.30.80.37 SOFIA DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:181 sofia/internal/3000@10.30.80.37 Standard DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/3000@10.30.80.37) State DESTROY going to sleep
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2000@10.30.88.12) State Change CS_REPORTING -> CS_DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_session.c:1646 Session 167 (sofia/internal/2000@10.30.88.12) Locked, Waiting on external entities
2016-05-23 11:19:31.009886 [NOTICE] switch_core_session.c:1664 Session 167 (sofia/internal/2000@10.30.88.12) Ended
2016-05-23 11:19:31.009886 [NOTICE] switch_core_session.c:1668 Close Channel sofia/internal/2000@10.30.88.12 [CS_DESTROY]
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2000@10.30.88.12) Running State Change CS_DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2000@10.30.88.12) State DESTROY
2016-05-23 11:19:31.009886 [DEBUG] mod_sofia.c:342 sofia/internal/2000@10.30.88.12 SOFIA DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2000@10.30.88.12 Standard DESTROY
2016-05-23 11:19:31.009886 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2000@10.30.88.12) State DESTROY going to sleep