Freeswitch HA sofia recover failing
We have a two node freeswitch cluster (time is synchronized between both servers). When we try to recover the call there is no audio, and we get the following in the log: 2016-09-20 17:37:35.289629 [NOTICE] sofia.c:8062 Hangup sofia/external/ 2505555555@456.456.456.456 [CS_RESET] [NORMAL_TEMPORARY_FAILURE] Any idea what might be wrong? below are the logs from server a and b ips and dns obfuscated. SERVER A 2016-09-20 17:37:20.788151 [NOTICE] switch_channel.c:1104 New Channel sofia/external/2505555555@456.456.456.456 [8e70d2d8-7f93-11e6-a71d- 79c835def150] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_NEW 2016-09-20 17:37:20.788151 [DEBUG] sofia.c:9587 sofia/external/2505555555 @456.456.456.456 receiving invite from 456.456.456.456:5060 version: 1.7.0 git 7258a24 2016-09-13 18:17:51Z 64bit 2016-09-20 17:37:20.788151 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [received][100] 2016-09-20 17:37:20.788151 [DEBUG] sofia.c:6973 Remote SDP: v=0 o=Itel 15821173 15821173 IN IP4 456.456.456.456 s=Itel c=IN IP4 456.456.456.456 t=0 0 m=audio 19772 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4197 Set telephone-event payload to 101@8000 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:3017 Set Codec sofia/external/2505555555@456.456.456.456 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2016-09-20 17:37:20.788151 [DEBUG] switch_core_codec.c:111 sofia/external/ 2505555555@456.456.456.456 Original read codec set to PCMU:0 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4542 Set telephone-event payload to 101@8000 2016-09-20 17:37:20.788151 [DEBUG] switch_core_media.c:4601 sofia/external/ 2505555555@456.456.456.456 Set 2833 dtmf send payload to 101 recv payload to 101 2016-09-20 17:37:20.788151 [DEBUG] sofia.c:7362 (sofia/external/2505555555@456.456.456.456) State Change CS_NEW -> CS_INIT 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:562 (sofia/external/2505555555@456.456.456.456) State NEW 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_INIT 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:586 (sofia/external/2505555555@456.456.456.456) State INIT 2016-09-20 17:37:20.788151 [DEBUG] mod_sofia.c:90 sofia/external/2505555555 @456.456.456.456 SOFIA INIT 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:40 sofia/external/2505555555@456.456.456.456 Standard INIT 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:48 (sofia/external/2505555555@456.456.456.456) State Change CS_INIT -> CS_ROUTING 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:586 (sofia/external/2505555555@456.456.456.456) State INIT going to sleep 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_ROUTING 2016-09-20 17:37:20.788151 [DEBUG] switch_channel.c:2249 (sofia/external/ 2505555555@456.456.456.456) Callstate Change DOWN -> RINGING 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:602 (sofia/external/2505555555@456.456.456.456) State ROUTING 2016-09-20 17:37:20.788151 [DEBUG] mod_sofia.c:143 sofia/external/2505555555 @456.456.456.456 SOFIA ROUTING 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:236 sofia/external/2505555555@456.456.456.456 Standard ROUTING 2016-09-20 17:37:20.788151 [INFO] mod_dialplan_xml.c:637 Processing SOKAMLOOPS BC <2505555555>->7786962265 in context public Dialplan: sofia/external/2505555555@456.456.456.456 parsing [public-> 7786962264] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [7786962264] destination_number(7786962265) =~ /^(7786962264)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [public-> 7786962265] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [7786962265] destination_number(7786962265) =~ /^(7786962265)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(call_direction=inbound) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(call_direction=inbound) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [call_direction]=[inbound] Dialplan: sofia/external/2505555555@456.456.456.456 Action set(domain_uuid=a5254a78-db77-4b8c-b333-78d95060f10f) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(domain_uuid=a5254a78-db77-4b8c-b333-78d95060f10f) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [domain_uuid]=[a5254a78-db77- 4b8c-b333-78d95060f10f] Dialplan: sofia/external/2505555555@456.456.456.456 Action set(domain_name= sipa.test.com) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(domain_name= sipa.test.com) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [domain_name]=[sipa.test.com] Dialplan: sofia/external/2505555555@456.456.456.456 Action transfer(2001 XML sipa.test.com) 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:286 (sofia/external/2505555555@456.456.456.456) State Change CS_ROUTING -> CS_EXECUTE 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:602 (sofia/external/2505555555@456.456.456.456) State ROUTING going to sleep 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_EXECUTE 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:609 (sofia/external/2505555555@456.456.456.456) State EXECUTE 2016-09-20 17:37:20.788151 [DEBUG] mod_sofia.c:198 sofia/external/2505555555 @456.456.456.456 SOFIA EXECUTE 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:328 sofia/external/2505555555@456.456.456.456 Standard EXECUTE EXECUTE sofia/external/2505555555@456.456.456.456 transfer(2001 XML sipa.test.com) 2016-09-20 17:37:20.788151 [DEBUG] switch_ivr.c:2160 (sofia/external/ 2505555555@456.456.456.456) State Change CS_EXECUTE -> CS_ROUTING 2016-09-20 17:37:20.788151 [NOTICE] switch_ivr.c:2167 Transfer sofia/external/2505555555@456.456.456.456 to XML[2001@sipa.test.com] 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:609 (sofia/external/2505555555@456.456.456.456) State EXECUTE going to sleep 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_ROUTING 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:602 (sofia/external/2505555555@456.456.456.456) State ROUTING 2016-09-20 17:37:20.788151 [DEBUG] mod_sofia.c:143 sofia/external/2505555555 @456.456.456.456 SOFIA ROUTING 2016-09-20 17:37:20.788151 [DEBUG] switch_core_state_machine.c:236 sofia/external/2505555555@456.456.456.456 Standard ROUTING 2016-09-20 17:37:20.788151 [INFO] mod_dialplan_xml.c:637 Processing SOKAMLOOPS BC <2505555555>->2001 in context sipa.test.com Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->user_exists] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(user_exists=true) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [user_exists]=[true] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_ destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(call_screen_enabled=false) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [call_screen_enabled]=[false] Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->user_exists] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(user_exists=true) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [user_exists]=[true] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_ destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(call_screen_enabled=false) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [call_screen_enabled]=[false] Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call-direction] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call-direction] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->variables] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->variables] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->user_record] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(user_record=) 2016-09-20 17:37:20.788151 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [user_record]=[UNDEF] Dialplan: sofia/external/2505555555@456.456.456.456 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE 2016-09-20 17:37:20.828076 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fa74404e4c0 Connected. 2016-09-20 17:37:20.828076 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fa74404e4c0 released. EXECUTE sofia/external/2505555555@456.456.456.456 set(from_user_exists=false) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [from_user_exists]=[false] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->user_record] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(user_record=) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [user_record]=[UNDEF] Dialplan: sofia/external/2505555555@456.456.456.456 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE 2016-09-20 17:37:20.828076 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fa74404e4c0 Connected. 2016-09-20 17:37:20.828076 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fa74404e4c0 released. EXECUTE sofia/external/2505555555@456.456.456.456 set(from_user_exists=false) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [from_user_exists]=[false] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->redial] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [redial] destination_number(2001) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/ ${destination_number}) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->redial] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [redial] destination_number(2001) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/ ${destination_number}) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->sbc1.1d10] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [sbc1.1d10] destination_number(2001) =~ /^\+?1?(\d{10})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->sbc2.1d10] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [sbc2.1d10] destination_number(2001) =~ /^\+?1?(\d{10})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->agent_status] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [agent_status] destination_number(2001) =~ /^\*22$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->agent_status] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [agent_status] destination_number(2001) =~ /^\*22$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->agent_status_id] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [agent_status_id] destination_number(2001) =~ /^\*23$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->agent_status_id] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [agent_status_id] destination_number(2001) =~ /^\*23$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->group-intercept] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [group-intercept] destination_number(2001) =~ /^\*8$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->group-intercept] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [group-intercept] destination_number(2001) =~ /^\*8$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->page-extension] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [page-extension] destination_number(2001) =~ /^\*8(\d{2,7})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->page-extension] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [page-extension] destination_number(2001) =~ /^\*8(\d{2,7})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->eavesdrop] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^\*33(\d{2,7})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->eavesdrop] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^\*33(\d{2,7})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_privacy] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_privacy] destination_number(2001) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_privacy] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_privacy] destination_number(2001) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_return] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_return] destination_number(2001) =~ /^\*69$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_return] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_return] destination_number(2001) =~ /^\*69$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->extension_queue] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [extension_queue] destination_number(2001) =~ /^\*800(.*)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->extension_queue] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [extension_queue] destination_number(2001) =~ /^\*800(.*)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->intercept-ext] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [intercept-ext] destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->intercept-ext] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [intercept-ext] destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->intercept-ext-polycom] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [intercept-ext-polycom] destination_number(2001) =~ /^\*97(\d+)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->dx] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [dx] destination_number(2001) =~ /^dx$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->dx] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [dx] destination_number(2001) =~ /^dx$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->att_xfer] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [att_xfer] destination_number(2001) =~ /^att_xfer$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->att_xfer] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [att_xfer] destination_number(2001) =~ /^att_xfer$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->extension-to-voicemail] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [extension-to-voicemail] username(2505555555) =~ /^2505555555$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [extension-to-voicemail] destination_number(2001) =~ /^2505555555$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->extension-to-voicemail] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [extension-to-voicemail] username(2505555555) =~ /^2505555555$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [extension-to-voicemail] destination_number(2001) =~ /^2505555555$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->send_to_voicemail] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [send_to_voicemail] destination_number(2001) =~ /^\*99(\d{2,10})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->send_to_voicemail] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [send_to_voicemail] destination_number(2001) =~ /^\*99(\d{2,10})$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->vmain] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [vmain] destination_number(2001) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->vmain] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [vmain] destination_number(2001) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->xfer_vm] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [xfer_vm] destination_number(2001) =~ /^xfer_vm$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->xfer_vm] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [xfer_vm] destination_number(2001) =~ /^xfer_vm$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_transfer] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_transfer] destination_number(2001) =~ /^is_transfer$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_transfer] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_transfer] destination_number(2001) =~ /^is_transfer$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->vmain_user] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [vmain_user] destination_number(2001) =~ /^\*97$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->vmain_user] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [vmain_user] destination_number(2001) =~ /^\*97$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->cf] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [cf] destination_number(2001) =~ /^cf$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->cf] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [cf] destination_number(2001) =~ /^cf$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->delay_echo] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [delay_echo] destination_number(2001) =~ /^\*9195$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->delay_echo] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [delay_echo] destination_number(2001) =~ /^\*9195$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->echo] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [echo] destination_number(2001) =~ /^\*9196$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->echo] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [echo] destination_number(2001) =~ /^\*9196$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_zrtp_secure] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 ANTI-Action eval(not_secure) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_zrtp_secure] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 ANTI-Action eval(not_secure) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->milliwatt] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [milliwatt] destination_number(2001) =~ /^\*9197$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->milliwatt] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [milliwatt] destination_number(2001) =~ /^\*9197$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_secure] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->is_secure] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->tone_stream] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [tone_stream] destination_number(2001) =~ /^\*9198$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->tone_stream] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [tone_stream] destination_number(2001) =~ /^\*9198$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->hold_music] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [hold_music] destination_number(2001) =~ /^\*9664$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->hold_music] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [hold_music] destination_number(2001) =~ /^\*9664$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->recordings] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [recordings] destination_number(2001) =~ /^\*(732)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->recordings] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [recordings] destination_number(2001) =~ /^\*(732)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->directory] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [directory] destination_number(2001) =~ /^\*411$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->directory] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [directory] destination_number(2001) =~ /^\*411$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->wake-up] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [wake-up] destination_number(2001) =~ /^\*(925)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->wake-up] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [wake-up] destination_number(2001) =~ /^\*(925)$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->valet_park] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->valet_park] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [valet_park] destination_number(2001) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->operator] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [operator] destination_number(2001) =~ /^0$|^operator$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->operator] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [operator] destination_number(2001) =~ /^0$|^operator$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->operator-forward] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [operator-forward] destination_number(2001) =~ /^\*000$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->operator-forward] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [operator-forward] destination_number(2001) =~ /^\*000$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->do-not-disturb] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [do-not-disturb] destination_number(2001) =~ /^\*78$|\*363$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [do-not-disturb] destination_number(2001) =~ /^\*79$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->do-not-disturb] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [do-not-disturb] destination_number(2001) =~ /^\*78$|\*363$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [do-not-disturb] destination_number(2001) =~ /^\*79$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call-forward] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*72$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*73$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*74$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call-forward] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*72$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*73$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call-forward] destination_number(2001) =~ /^\*74$/ break=on-true Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->follow-me] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [follow-me] destination_number(2001) =~ /^\*21$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->follow-me] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [follow-me] destination_number(2001) =~ /^\*21$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->clear_sip_auto_answer] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->clear_sip_auto_answer] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->talking clock date and time] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [talking clock date and time] destination_number(2001) =~ /^\*9172$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->talking clock time] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [talking clock time] destination_number(2001) =~ /^\*9170$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->talking clock date] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [talking clock date] destination_number(2001) =~ /^\*9171$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_screen] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->call_screen] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->local_extension] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action export(dialed_extension=${destination_number}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 export(dialed_extension=2001) 2016-09-20 17:37:20.828076 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[2001] Dialplan: sofia/external/2505555555@456.456.456.456 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [local_extension] ${sip_authorized}() =~ /true/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 ANTI-Action set(bind_target=peer) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(bind_target=peer) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [bind_target]=[peer] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*1,exec:execute_extension,dx XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*2,exec:record_session,${ recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${ strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*3,exec:execute_extension,cf XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*4,exec:execute_extension,att_xfer XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action digit_action_set_realm(local) Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(hangup_after_bridge=true) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(continue_on_fail=true) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-call_return/${dialed_ extension}/${caller_id_number}) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)}) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(api_hangup_hook=lua app.lua hangup) Dialplan: sofia/external/2505555555@456.456.456.456 Action bridge(user/${destination_number}@${domain_name}) Dialplan: sofia/external/2505555555@456.456.456.456 Action lua(app.lua failure_handler) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->local_extension] continue=true Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action export(dialed_extension=${destination_number}) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 export(dialed_extension=2001) 2016-09-20 17:37:20.828076 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[2001] Dialplan: sofia/external/2505555555@456.456.456.456 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination}) Dialplan: sofia/external/2505555555@456.456.456.456 Regex (FAIL) [local_extension] ${sip_authorized}() =~ /true/ break=never Dialplan: sofia/external/2505555555@456.456.456.456 ANTI-Action set(bind_target=peer) INLINE EXECUTE sofia/external/2505555555@456.456.456.456 set(bind_target=peer) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [bind_target]=[peer] Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*1,exec:execute_extension,dx XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*2,exec:record_session,${ recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${ strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*3,exec:execute_extension,cf XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action bind_digit_action(local,*4,exec:execute_extension,att_xfer XML ${context},${bind_target}) Dialplan: sofia/external/2505555555@456.456.456.456 Action digit_action_set_realm(local) Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [local_extension] () =~ // break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action set(hangup_after_bridge=true) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(continue_on_fail=true) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-call_return/${dialed_ extension}/${caller_id_number}) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)}) Dialplan: sofia/external/2505555555@456.456.456.456 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(api_hangup_hook=lua app.lua hangup) Dialplan: sofia/external/2505555555@456.456.456.456 Action bridge(user/${destination_number}@${domain_name}) Dialplan: sofia/external/2505555555@456.456.456.456 Action lua(app.lua failure_handler) Dialplan: sofia/external/2505555555@456.456.456.456 parsing [sipa.test.com->voicemail] continue=false Dialplan: sofia/external/2505555555@456.456.456.456 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external/2505555555@456.456.456.456 Action answer() Dialplan: sofia/external/2505555555@456.456.456.456 Action sleep(1000) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(voicemail_action=save) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(voicemail_id=${destination_number}) Dialplan: sofia/external/2505555555@456.456.456.456 Action set(voicemail_profile=default) Dialplan: sofia/external/2505555555@456.456.456.456 Action lua(app.lua voicemail) 2016-09-20 17:37:20.828076 [DEBUG] switch_core_state_machine.c:286 (sofia/external/2505555555@456.456.456.456) State Change CS_ROUTING -> CS_EXECUTE 2016-09-20 17:37:20.828076 [DEBUG] switch_core_state_machine.c:602 (sofia/external/2505555555@456.456.456.456) State ROUTING going to sleep 2016-09-20 17:37:20.828076 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_EXECUTE 2016-09-20 17:37:20.828076 [DEBUG] switch_core_state_machine.c:609 (sofia/external/2505555555@456.456.456.456) State EXECUTE 2016-09-20 17:37:20.828076 [DEBUG] mod_sofia.c:198 sofia/external/2505555555 @456.456.456.456 SOFIA EXECUTE 2016-09-20 17:37:20.828076 [DEBUG] switch_core_state_machine.c:328 sofia/external/2505555555@456.456.456.456 Standard EXECUTE EXECUTE sofia/external/2505555555@456.456.456.456 set(extension_uuid=054c1f2c-e5a3-48d3-82f9-7c3b3e9e6367) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [extension_uuid]=[054c1f2c- e5a3-48d3-82f9-7c3b3e9e6367] EXECUTE sofia/external/2505555555@456.456.456.456 set(hold_music=local_stream://default) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [hold_music]=[local_stream://default] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_all_enabled=) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_all_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_all_destination=) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_all_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_busy_enabled=) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_busy_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_busy_destination=) 2016-09-20 17:37:20.828076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_busy_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_no_answer_enabled=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_no_answer_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_no_answer_ destination=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_no_answer_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_user_not_ registered_enabled=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_user_not_registered_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_user_not_ registered_destination=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_user_not_registered_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(do_not_disturb=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [do_not_disturb]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(call_timeout=30) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [call_timeout]=[30] EXECUTE sofia/external/2505555555@456.456.456.456 set(missed_call_app=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [missed_call_app]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(missed_call_data=) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [missed_call_data]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(extension_uuid=054c1f2c-e5a3-48d3-82f9-7c3b3e9e6367) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [extension_uuid]=[054c1f2c- e5a3-48d3-82f9-7c3b3e9e6367] EXECUTE sofia/external/2505555555@456.456.456.456 set(hold_music=local_stream://default) 2016-09-20 17:37:20.848079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [hold_music]=[local_stream://default] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_all_enabled=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_all_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_all_destination=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_all_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_busy_enabled=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_busy_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_busy_destination=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_busy_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_no_answer_enabled=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_no_answer_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_no_answer_ destination=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_no_answer_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_user_not_ registered_enabled=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_user_not_registered_enabled]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(forward_user_not_ registered_destination=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [forward_user_not_registered_destination]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(do_not_disturb=) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [do_not_disturb]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(call_timeout=30) 2016-09-20 17:37:20.868076 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [call_timeout]=[30] EXECUTE sofia/external/2505555555@456.456.456.456 set(missed_call_app=) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [missed_call_app]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 set(missed_call_data=) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [missed_call_data]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 export(origination_callee_id_name=2001) 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[2001] EXECUTE sofia/external/2505555555@456.456.456.456 set(RFC2822_DATE=Tue, 20 Sep 2016 17:37:20 -0700) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [RFC2822_DATE]=[Tue, 20 Sep 2016 17:37:20 -0700] EXECUTE sofia/external/2505555555@456.456.456.456 export(origination_callee_id_name=2001) 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[2001] EXECUTE sofia/external/2505555555@456.456.456.456 set(RFC2822_DATE=Tue, 20 Sep 2016 17:37:20 -0700) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [RFC2822_DATE]=[Tue, 20 Sep 2016 17:37:20 -0700] EXECUTE sofia/external/2505555555@456.456.456.456 hash(insert/sipa.test.com- last_dial/2505555555/2001) EXECUTE sofia/external/2505555555@456.456.456.456 hash(insert/sipa.test.com- last_dial/2505555555/2001) EXECUTE sofia/external/2505555555@456.456.456.456 eval(not_secure) EXECUTE sofia/external/2505555555@456.456.456.456 eval(not_secure) EXECUTE sofia/external/2505555555@456.456.456.456 limit(hash sipa.test.com 2001 ) 2016-09-20 17:37:20.888079 [DEBUG] switch_limit.c:126 incr called: sipa.test.com_2001 max:-1, interval:0 2016-09-20 17:37:20.888079 [DEBUG] mod_hash.c:194 Usage for sipa.test.com_2001 is now 1 EXECUTE sofia/external/2505555555@456.456.456.456 bind_digit_action(local,*1,exec:execute_extension,dx XML sipa.test.com,peer) 2016-09-20 17:37:20.888079 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local' 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *1/local/0 callback: 0x7fa72544ba00 data: 0x7fa6c40246d0 EXECUTE sofia/external/2505555555@456.456.456.456 bind_digit_action(local,*2,exec:record_session,/usr/ local/freeswitch/recordings/sipa.test.com/archive/2016/Sep/ 20/8e70d2d8-7f93-11e6-a71d-79c835def150.wav,peer) 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *2/local/0 callback: 0x7fa72544ba00 data: 0x7fa6c4024928 EXECUTE sofia/external/2505555555@456.456.456.456 bind_digit_action(local,*3,exec:execute_extension,cf XML sipa.test.com,peer) 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *3/local/0 callback: 0x7fa72544ba00 data: 0x7fa6c4024ae0 EXECUTE sofia/external/2505555555@456.456.456.456 bind_digit_action(local,*4,exec:execute_extension,att_xfer XML sipa.test.com ,peer) 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *4/local/0 callback: 0x7fa72544ba00 data: 0x7fa6c4024c50 EXECUTE sofia/external/2505555555@456.456.456.456 digit_action_set_realm(local) EXECUTE sofia/external/2505555555@456.456.456.456 set(hangup_after_bridge=true) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [hangup_after_bridge]=[true] EXECUTE sofia/external/2505555555@456.456.456.456 set(continue_on_fail=true) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [continue_on_fail]=[true] EXECUTE sofia/external/2505555555@456.456.456.456 hash(insert/sipa.test.com- call_return/2001/2505555555) EXECUTE sofia/external/2505555555@456.456.456.456 hash(insert/sipa.test.com- last_dial_ext/2001/8e70d2d8-7f93-11e6-a71d-79c835def150) EXECUTE sofia/external/2505555555@456.456.456.456 set(called_party_call_group=) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [called_party_call_group]=[UNDEF] EXECUTE sofia/external/2505555555@456.456.456.456 hash(insert/sipa.test.com- last_dial//8e70d2d8-7f93-11e6-a71d-79c835def150) EXECUTE sofia/external/2505555555@456.456.456.456 set(api_hangup_hook=lua app.lua hangup) 2016-09-20 17:37:20.888079 [DEBUG] mod_dptools.c:1519 SET sofia/external/ 2505555555@456.456.456.456 [api_hangup_hook]=[lua app.lua hangup] EXECUTE sofia/external/2505555555@456.456.456.456 bridge(user/ 2001@sipa.test.com) 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [dialed_extension]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [dialed_extension]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [origination_callee_id_name]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [origination_callee_id_name]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_originate.c:2138 Parsing global variables 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [dialed_extension]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [dialed_extension]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [origination_callee_id_name]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_channel.c:1250 sofia/external/ 2505555555@456.456.456.456 EXPORTING[export_vars] [origination_callee_id_name]=[2001] to event 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_originate.c:2138 Parsing global variables 2016-09-20 17:37:20.888079 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2001@72.143.224.138:20365 [8e7f1640-7f93-11e6-a766- 79c835def150] 2016-09-20 17:37:20.888079 [DEBUG] mod_sofia.c:4753 (sofia/internal/ 2001@72.143.224.138:20365) State Change CS_NEW -> CS_INIT 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_INIT 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2001@72.143.224.138:20365) State INIT 2016-09-20 17:37:20.888079 [DEBUG] mod_sofia.c:90 sofia/internal/ 2001@72.143.224.138:20365 SOFIA INIT 2016-09-20 17:37:20.888079 [DEBUG] sofia_glue.c:1282 sofia/internal/ 2001@72.143.224.138:20365 sending invite version: 1.7.0 git 7258a24 2016-09-13 18:17:51Z 64bit Local SDP: v=0 o=FreeSWITCH 1474397650 1474397651 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 20590 RTP/AVP 0 9 8 3 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2001@72.143.224.138:20365 Standard INIT 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2001@72.143.224.138:20365) State Change CS_INIT -> CS_ROUTING 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2001@72.143.224.138:20365) State INIT going to sleep 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_ROUTING 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2001@72.143.224.138:20365) State ROUTING 2016-09-20 17:37:20.888079 [DEBUG] mod_sofia.c:143 sofia/internal/ 2001@72.143.224.138:20365 SOFIA ROUTING 2016-09-20 17:37:20.888079 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/2001@72.143.224.138:20365) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2001@72.143.224.138:20365) State ROUTING going to sleep 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_CONSUME_MEDIA 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2001@72.143.224.138:20365) State CONSUME_MEDIA 2016-09-20 17:37:20.888079 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2001@72.143.224.138:20365) State CONSUME_MEDIA going to sleep 2016-09-20 17:37:20.888079 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [calling][0] 2016-09-20 17:37:22.228117 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [proceeding][180] 2016-09-20 17:37:22.228117 [NOTICE] sofia.c:7071 Ring-Ready sofia/internal/ 2001@72.143.224.138:20365! 2016-09-20 17:37:22.228117 [DEBUG] switch_channel.c:3343 (sofia/internal/ 2001@72.143.224.138:20365) Callstate Change DOWN -> RINGING 2016-09-20 17:37:22.248125 [NOTICE] mod_sofia.c:2216 Ring-Ready sofia/external/2505555555@456.456.456.456! 2016-09-20 17:37:22.248125 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [early][180] 2016-09-20 17:37:22.248125 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/external/2505555555@456.456.456.456! 2016-09-20 17:37:23.828155 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [completing][200] 2016-09-20 17:37:23.828155 [DEBUG] sofia.c:6973 Remote SDP: v=0 o=Zoiper 0 1 IN IP4 25.171.247.182 s=Zoiper c=IN IP4 25.171.247.182 t=0 0 m=audio 54200 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2016-09-20 17:37:23.828155 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [ready][200] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4197 Set telephone-event payload to 101@8000 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:3017 Set Codec sofia/internal/2001@72.143.224.138:20365 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2016-09-20 17:37:23.848111 [DEBUG] switch_core_codec.c:111 sofia/internal/ 2001@72.143.224.138:20365 Original read codec set to PCMU:0 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4542 Set telephone-event payload to 101@8000 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:4601 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf send payload to 101 recv payload to 101 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6438 AUDIO RTP [sofia/internal/2001@72.143.224.138:20365] 123.123.123.123 port 20590 -> 25.171.247.182 port 54200 codec: 0 ms: 20 2016-09-20 17:37:23.848111 [DEBUG] switch_rtp.c:3838 Starting timer [soft] 160 bytes per 20ms 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6737 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf send payload to 101 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6744 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf receive payload to 101 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6767 sofia/internal/ 2001@72.143.224.138:20365 Set rtp dtmf delay to 40 2016-09-20 17:37:23.848111 [NOTICE] sofia.c:8007 Channel [sofia/internal/ 2001@72.143.224.138:20365] has been answered 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6438 AUDIO RTP [sofia/external/2505555555@456.456.456.456] 123.123.123.123 port 30642 -> 456.456.456.456 port 19772 codec: 0 ms: 20 2016-09-20 17:37:23.848111 [DEBUG] switch_rtp.c:3838 Starting timer [soft] 160 bytes per 20ms 2016-09-20 17:37:23.848111 [DEBUG] switch_channel.c:3770 (sofia/internal/ 2001@72.143.224.138:20365) Callstate Change RINGING -> ACTIVE 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6737 sofia/external/ 2505555555@456.456.456.456 Set 2833 dtmf send payload to 101 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6744 sofia/external/ 2505555555@456.456.456.456 Set 2833 dtmf receive payload to 101 2016-09-20 17:37:23.848111 [DEBUG] switch_core_media.c:6767 sofia/external/ 2505555555@456.456.456.456 Set rtp dtmf delay to 40 2016-09-20 17:37:23.848111 [DEBUG] mod_sofia.c:822 Local SDP sofia/external/ 2505555555@456.456.456.456: v=0 o=FreeSWITCH 1474387601 1474387602 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 30642 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2016-09-20 17:37:23.848111 [NOTICE] switch_ivr_originate.c:3628 Channel [sofia/external/2505555555@456.456.456.456] has been answered 2016-09-20 17:37:23.848111 [DEBUG] switch_channel.c:3770 (sofia/external/ 2505555555@456.456.456.456) Callstate Change RINGING -> ACTIVE 2016-09-20 17:37:23.848111 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [completed][200] 2016-09-20 17:37:23.848111 [DEBUG] switch_ivr_originate.c:3686 Originate Resulted in Success: [sofia/internal/2001@72.143.224.138:20365] 2016-09-20 17:37:23.848111 [DEBUG] switch_ivr_originate.c:3686 Originate Resulted in Success: [sofia/internal/2001@72.143.224.138:20365] 2016-09-20 17:37:23.848111 [DEBUG] switch_ivr_bridge.c:1599 (sofia/internal/ 2001@72.143.224.138:20365) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2016-09-20 17:37:23.848111 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_EXCHANGE_MEDIA 2016-09-20 17:37:23.848111 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/2001@72.143.224.138:20365) State EXCHANGE_MEDIA 2016-09-20 17:37:23.848111 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2016-09-20 17:37:23.848111 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [ready][200] 2016-09-20 17:37:24.028124 [DEBUG] switch_rtp.c:6739 Correct audio ip/port confirmed. 2016-09-20 17:37:24.128112 [INFO] switch_rtp.c:6701 Auto Changing audio port from 25.171.247.182:54200 to 72.143.224.138:20373 2016-09-20 17:37:26.348133 [DEBUG] switch_rtp.c:6962 RTP RECV DTMF 8:960 2016-09-20 17:37:26.348133 [INFO] switch_channel.c:515 RECV DTMF 8:960 2016-09-20 17:37:26.348133 [DEBUG] mod_dptools.c:132 sofia/internal/ 2001@72.143.224.138:20365 Digit NOT match binding [8] 2016-09-20 17:37:26.348133 [INFO] switch_channel.c:515 RECV DTMF 8:2000 2016-09-20 17:37:26.348133 [DEBUG] switch_channel.c:611 sofia/internal/ 2001@72.143.224.138:20365 Queue dtmf digit=8 ms=250 samples=2000 2016-09-20 17:37:26.348133 [DEBUG] switch_rtp.c:4943 Send start packet for [8] ts=2079523031 dur=160/160/2000 seq=62866 lw=2079523031 2016-09-20 17:37:26.368123 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=320/320/2000 seq=62867 lw=2079523191 2016-09-20 17:37:26.388127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=480/480/2000 seq=62868 lw=2079523351 2016-09-20 17:37:26.388127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=640/640/2000 seq=62869 lw=2079523511 2016-09-20 17:37:26.388127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=800/800/2000 seq=62870 lw=2079523671 2016-09-20 17:37:26.388127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=960/960/2000 seq=62871 lw=2079523831 2016-09-20 17:37:26.428078 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1120/1120/2000 seq=62872 lw=2079523991 2016-09-20 17:37:26.448180 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1280/1280/2000 seq=62873 lw=2079524151 2016-09-20 17:37:26.448180 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1440/1440/2000 seq=62874 lw=2079524311 2016-09-20 17:37:26.488089 [DEBUG] switch_rtp.c:6962 RTP RECV DTMF 8:960 2016-09-20 17:37:26.488089 [INFO] switch_channel.c:515 RECV DTMF 8:960 2016-09-20 17:37:26.488089 [DEBUG] mod_dptools.c:132 sofia/internal/ 2001@72.143.224.138:20365 Digit NOT match binding [8] 2016-09-20 17:37:26.488089 [INFO] switch_channel.c:515 RECV DTMF 8:2000 2016-09-20 17:37:26.488089 [DEBUG] switch_channel.c:611 sofia/internal/ 2001@72.143.224.138:20365 Queue dtmf digit=8 ms=250 samples=2000 2016-09-20 17:37:26.488089 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1600/1600/2000 seq=62875 lw=2079524471 2016-09-20 17:37:26.508075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1760/1760/2000 seq=62876 lw=2079524631 2016-09-20 17:37:26.508075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079523031 dur=1920/1920/2000 seq=62877 lw=2079524791 2016-09-20 17:37:26.528109 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079523031 dur=2080/2080/2000 seq=62878 lw=2079524791 2016-09-20 17:37:26.528109 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079523031 dur=2080/2080/2000 seq=62879 lw=2079524791 2016-09-20 17:37:26.528109 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079523031 dur=2080/2080/2000 seq=62880 lw=2079524791 2016-09-20 17:37:26.528109 [DEBUG] switch_rtp.c:4795 Queue digit delay of 40ms 2016-09-20 17:37:26.568142 [DEBUG] switch_rtp.c:4943 Send start packet for [8] ts=2079526071 dur=160/160/2000 seq=62883 lw=2079526071 2016-09-20 17:37:26.588110 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=320/320/2000 seq=62884 lw=2079526231 2016-09-20 17:37:26.588110 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=480/480/2000 seq=62885 lw=2079526391 2016-09-20 17:37:26.588110 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=640/640/2000 seq=62886 lw=2079526551 2016-09-20 17:37:26.628074 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=800/800/2000 seq=62887 lw=2079526711 2016-09-20 17:37:26.628074 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=960/960/2000 seq=62888 lw=2079526871 2016-09-20 17:37:26.648076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1120/1120/2000 seq=62889 lw=2079527031 2016-09-20 17:37:26.668076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1280/1280/2000 seq=62890 lw=2079527191 2016-09-20 17:37:26.688128 [DEBUG] switch_rtp.c:6962 RTP RECV DTMF 8:960 2016-09-20 17:37:26.688128 [INFO] switch_channel.c:515 RECV DTMF 8:960 2016-09-20 17:37:26.688128 [DEBUG] mod_dptools.c:132 sofia/internal/ 2001@72.143.224.138:20365 Digit NOT match binding [8] 2016-09-20 17:37:26.688128 [INFO] switch_channel.c:515 RECV DTMF 8:2000 2016-09-20 17:37:26.688128 [DEBUG] switch_channel.c:611 sofia/internal/ 2001@72.143.224.138:20365 Queue dtmf digit=8 ms=250 samples=2000 2016-09-20 17:37:26.688128 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1440/1440/2000 seq=62891 lw=2079527351 2016-09-20 17:37:26.688128 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1600/1600/2000 seq=62892 lw=2079527511 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1760/1760/2000 seq=62893 lw=2079527671 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079526071 dur=1920/1920/2000 seq=62894 lw=2079527831 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079526071 dur=2080/2080/2000 seq=62895 lw=2079527831 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079526071 dur=2080/2080/2000 seq=62896 lw=2079527831 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079526071 dur=2080/2080/2000 seq=62897 lw=2079527831 2016-09-20 17:37:26.728126 [DEBUG] switch_rtp.c:4795 Queue digit delay of 40ms 2016-09-20 17:37:26.828141 [DEBUG] switch_rtp.c:6962 RTP RECV DTMF 8:960 2016-09-20 17:37:26.828141 [INFO] switch_channel.c:515 RECV DTMF 8:960 2016-09-20 17:37:26.828141 [DEBUG] mod_dptools.c:132 sofia/internal/ 2001@72.143.224.138:20365 Digit NOT match binding [8] 2016-09-20 17:37:26.828141 [INFO] switch_channel.c:515 RECV DTMF 8:2000 2016-09-20 17:37:26.828141 [DEBUG] switch_channel.c:611 sofia/internal/ 2001@72.143.224.138:20365 Queue dtmf digit=8 ms=250 samples=2000 2016-09-20 17:37:26.888119 [DEBUG] switch_rtp.c:4943 Send start packet for [8] ts=2079528951 dur=160/160/2000 seq=62900 lw=2079528951 2016-09-20 17:37:26.888119 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=320/320/2000 seq=62901 lw=2079529111 2016-09-20 17:37:26.928075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=480/480/2000 seq=62902 lw=2079529271 2016-09-20 17:37:26.928075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=640/640/2000 seq=62903 lw=2079529431 2016-09-20 17:37:26.948077 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=800/800/2000 seq=62904 lw=2079529591 2016-09-20 17:37:26.948077 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=960/960/2000 seq=62905 lw=2079529751 2016-09-20 17:37:26.968075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1120/1120/2000 seq=62906 lw=2079529911 2016-09-20 17:37:26.988075 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1280/1280/2000 seq=62907 lw=2079530071 2016-09-20 17:37:27.008076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1440/1440/2000 seq=62908 lw=2079530231 2016-09-20 17:37:27.028074 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1600/1600/2000 seq=62909 lw=2079530391 2016-09-20 17:37:27.028074 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1760/1760/2000 seq=62910 lw=2079530551 2016-09-20 17:37:27.048076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079528951 dur=1920/1920/2000 seq=62911 lw=2079530711 2016-09-20 17:37:27.048076 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079528951 dur=2080/2080/2000 seq=62912 lw=2079530711 2016-09-20 17:37:27.048076 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079528951 dur=2080/2080/2000 seq=62913 lw=2079530711 2016-09-20 17:37:27.048076 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079528951 dur=2080/2080/2000 seq=62914 lw=2079530711 2016-09-20 17:37:27.048076 [DEBUG] switch_rtp.c:4795 Queue digit delay of 40ms 2016-09-20 17:37:27.088092 [DEBUG] switch_rtp.c:4943 Send start packet for [8] ts=2079530551 dur=160/160/2000 seq=62917 lw=2079530551 2016-09-20 17:37:27.108125 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=320/320/2000 seq=62918 lw=2079530711 2016-09-20 17:37:27.128106 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=480/480/2000 seq=62919 lw=2079530871 2016-09-20 17:37:27.128106 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=640/640/2000 seq=62920 lw=2079531031 2016-09-20 17:37:27.128106 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=800/800/2000 seq=62921 lw=2079531191 2016-09-20 17:37:27.128106 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=960/960/2000 seq=62922 lw=2079531351 2016-09-20 17:37:27.168076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1120/1120/2000 seq=62923 lw=2079531511 2016-09-20 17:37:27.188127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1280/1280/2000 seq=62924 lw=2079531671 2016-09-20 17:37:27.188127 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1440/1440/2000 seq=62925 lw=2079531831 2016-09-20 17:37:27.228074 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1600/1600/2000 seq=62926 lw=2079531991 2016-09-20 17:37:27.248076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1760/1760/2000 seq=62927 lw=2079532151 2016-09-20 17:37:27.248076 [DEBUG] switch_rtp.c:4842 Send middle packet for [8] ts=2079530551 dur=1920/1920/2000 seq=62928 lw=2079532311 2016-09-20 17:37:27.268080 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079530551 dur=2080/2080/2000 seq=62929 lw=2079532311 2016-09-20 17:37:27.268080 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079530551 dur=2080/2080/2000 seq=62930 lw=2079532311 2016-09-20 17:37:27.268080 [DEBUG] switch_rtp.c:4842 Send end packet for [8] ts=2079530551 dur=2080/2080/2000 seq=62931 lw=2079532311 2016-09-20 17:37:27.268080 [DEBUG] switch_rtp.c:4795 Queue digit delay of 40ms freeswitch@fusion> SERVER B freeswitch@fusion> sofia recover Recovered 2 call(s) 2016-09-20 17:37:35.289629 [NOTICE] switch_channel.c:1104 New Channel sofia/external/2505555555@456.456.456.456 [8e70d2d8-7f93-11e6-a71d- 79c835def150] 2016-09-20 17:37:35.289629 [NOTICE] switch_channel.c:1102 Rename Channel sofia/external/2505555555@456.456.456.456->sofia/external/2505555555@456.456.456.456 [8e70d2d8-7f93-11e6-a71d-79c835def150] 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:3017 Set Codec sofia/external/2505555555@456.456.456.456 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2016-09-20 17:37:35.289629 [DEBUG] switch_core_codec.c:111 sofia/external/ 2505555555@456.456.456.456 Original read codec set to PCMU:0 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6438 AUDIO RTP [sofia/external/2505555555@456.456.456.456] 123.123.123.123 port 30642 -> 456.456.456.456 port 19772 codec: 0 ms: 20 2016-09-20 17:37:35.289629 [DEBUG] switch_rtp.c:3838 Starting timer [soft] 160 bytes per 20ms 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6737 sofia/external/ 2505555555@456.456.456.456 Set 2833 dtmf send payload to 101 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6744 sofia/external/ 2505555555@456.456.456.456 Set 2833 dtmf receive payload to 101 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6767 sofia/external/ 2505555555@456.456.456.456 Set rtp dtmf delay to 40 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6773 Set comfort noise payload to 13 2016-09-20 17:37:35.289629 [DEBUG] switch_core_sqldb.c:3036 (sofia/external/ 2505555555@456.456.456.456) State Change CS_NEW -> CS_INIT 2016-09-20 17:37:35.289629 [NOTICE] switch_core_sqldb.c:3037 Resurrecting fallen channel sofia/external/2505555555@456.456.456.456 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_INIT 2016-09-20 17:37:35.289629 [DEBUG] switch_channel.c:2251 (sofia/external/ 2505555555@456.456.456.456) Callstate Change DOWN -> ACTIVE 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:586 (sofia/external/2505555555@456.456.456.456) State INIT 2016-09-20 17:37:35.289629 [DEBUG] mod_sofia.c:90 sofia/external/2505555555 @456.456.456.456 SOFIA INIT 2016-09-20 17:37:35.289629 [DEBUG] sofia_glue.c:1282 sofia/external/ 2505555555@456.456.456.456 sending invite version: 1.7.0 git 7258a24 2016-09-13 18:17:51Z 64bit Local SDP: v=0 o=FreeSWITCH 1474387613 1474387615 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 30642 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/0 a=fmtp:101 0-16 a=rtpmap:13 CN/0 a=ptime:20 a=sendrecv 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:40 sofia/external/2505555555@456.456.456.456 Standard INIT 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:43 (sofia/external/2505555555@456.456.456.456) State Change CS_INIT -> CS_RESET send 1123 bytes to udp/[456.456.456.456]:5060 at 17:37:35.295527: ------------------------------------------------------------------------ INVITE sip:2505555555@456.456.456.456:5060 SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123:5080;rport;branch=z9hG4bKr2jctgUFrDmpK Route: <sip:2505555555@456.456.456.456:5060;transport=udp> Max-Forwards: 69 From: <sip:7786962265@123.123.123.123:5080>;tag=28mBjg3pvH3SK To: "SOKAMLOOPS BC " <sip:2505555555@456.456.456.456>;tag=as755f2144 Call-ID: 3a3825c20a395c2f02a629bd22ef969c@456.456.456.456:5060 CSeq: 96873063 INVITE Contact: <sip:2505555555@123.123.123.123:5080> User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp e Content-Disposition: session Content-Length: 244 X-FS-Support: update_display,send_info Remote-Party-ID: "7786962265" <sip:7786962265@456.456.456. 456>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1474387613 1474387615 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 30642 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/0 a=fmtp:101 0-16 a=rtpmap:13 CN/0 a=ptime:20 ------------------------------------------------------------------------ 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:586 (sofia/external/2505555555@456.456.456.456) State INIT going to sleep 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_RESET 2016-09-20 17:37:35.289629 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [calling][0] 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:605 (sofia/external/2505555555@456.456.456.456) State RESET 2016-09-20 17:37:35.289629 [DEBUG] mod_sofia.c:161 sofia/external/2505555555 @456.456.456.456 SOFIA RESET 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:188 sofia/external/2505555555@456.456.456.456 Standard RESET 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:605 (sofia/external/2505555555@456.456.456.456) State RESET going to sleep 2016-09-20 17:37:35.289629 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2001@72.143.224.138:20365 [8e7f1640-7f93-11e6-a766- 79c835def150] 2016-09-20 17:37:35.289629 [NOTICE] switch_channel.c:1102 Rename Channel sofia/internal/2001@72.143.224.138:20365->sofia/internal/ 2001@72.143.224.138:20365 [8e7f1640-7f93-11e6-a766-79c835def150] 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:3017 Set Codec sofia/internal/2001@72.143.224.138:20365 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2016-09-20 17:37:35.289629 [DEBUG] switch_core_codec.c:111 sofia/internal/ 2001@72.143.224.138:20365 Original read codec set to PCMU:0 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6438 AUDIO RTP [sofia/internal/2001@72.143.224.138:20365] 123.123.123.123 port 20590 -> 25.171.247.182 port 54200 codec: 0 ms: 20 2016-09-20 17:37:35.289629 [DEBUG] switch_rtp.c:3838 Starting timer [soft] 160 bytes per 20ms 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6737 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf send payload to 101 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6744 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf receive payload to 101 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6767 sofia/internal/ 2001@72.143.224.138:20365 Set rtp dtmf delay to 40 2016-09-20 17:37:35.289629 [DEBUG] switch_core_media.c:6773 Set comfort noise payload to 13 2016-09-20 17:37:35.289629 [DEBUG] switch_core_sqldb.c:3036 (sofia/internal/ 2001@72.143.224.138:20365) State Change CS_NEW -> CS_INIT 2016-09-20 17:37:35.289629 [NOTICE] switch_core_sqldb.c:3037 Resurrecting fallen channel sofia/internal/2001@72.143.224.138:20365 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_INIT 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2001@72.143.224.138:20365) State INIT 2016-09-20 17:37:35.289629 [DEBUG] mod_sofia.c:90 sofia/internal/ 2001@72.143.224.138:20365 SOFIA INIT 2016-09-20 17:37:35.289629 [DEBUG] sofia_glue.c:1282 sofia/internal/ 2001@72.143.224.138:20365 sending invite version: 1.7.0 git 7258a24 2016-09-13 18:17:51Z 64bit Local SDP: v=0 o=FreeSWITCH 1474397665 1474397667 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 20590 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/0 a=fmtp:101 0-16 a=rtpmap:13 CN/0 a=ptime:20 a=sendrecv 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2001@72.143.224.138:20365 Standard INIT 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:43 (sofia/internal/2001@72.143.224.138:20365) State Change CS_INIT -> CS_RESET send 1323 bytes to udp/[72.143.224.138]:20365 at 17:37:35.299037: ------------------------------------------------------------------------ INVITE sip:2001@72.143.224.138:20365;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123;rport;branch=z9hG4bK0DU6aXj2FvHBp Via: SIP/2.0/UDP 123.123.123.123;rport=5060;branch=z9hG4bKvXKtj06r89vca Max-Forwards: 68 From: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com>;tag=vDHFU74UXyNmS To: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;tag=14496d0a Call-ID: 65dd6ddc-fa36-1234-b68d-1803730b83c5 CSeq: 96873063 INVITE Contact: <sip:2001@123.123.123.123:5060> User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 244 X-FS-Support: update_display,send_info Remote-Party-ID: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com> ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1474397665 1474397667 IN IP4 123.123.123.123 s=FreeSWITCH c=IN IP4 123.123.123.123 t=0 0 m=audio 20590 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/0 a=fmtp:101 0-16 a=rtpmap:13 CN/0 a=ptime:20 ------------------------------------------------------------------------ 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2001@72.143.224.138:20365) State INIT going to sleep 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_RESET 2016-09-20 17:37:35.289629 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [calling][0] 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:605 (sofia/internal/2001@72.143.224.138:20365) State RESET 2016-09-20 17:37:35.289629 [DEBUG] mod_sofia.c:161 sofia/internal/ 2001@72.143.224.138:20365 SOFIA RESET 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:188 sofia/internal/2001@72.143.224.138:20365 Standard RESET 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:605 (sofia/internal/2001@72.143.224.138:20365) State RESET going to sleep recv 520 bytes from udp/[456.456.456.456]:5060 at 17:37:35.303679: ------------------------------------------------------------------------ SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/UDP 123.123.123.123:5080;branch= z9hG4bKr2jctgUFrDmpK;received=123.123.123.123;rport=5080 From: <sip:7786962265@123.123.123.123:5080>;tag=28mBjg3pvH3SK To: "SOKAMLOOPS BC " <sip:2505555555@456.456.456.456>;tag=as755f2144 Call-ID: 3a3825c20a395c2f02a629bd22ef969c@456.456.456.456:5060 CSeq: 96873063 INVITE Server: Itelnetworks Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces Content-Length: 0 ------------------------------------------------------------------------ send 430 bytes to udp/[456.456.456.456]:5060 at 17:37:35.303739: ------------------------------------------------------------------------ ACK sip:2505555555@456.456.456.456:5060 SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123:5080;rport;branch=z9hG4bKr2jctgUFrDmpK Route: <sip:2505555555@456.456.456.456:5060;transport=udp> Max-Forwards: 69 From: <sip:7786962265@123.123.123.123:5080>;tag=28mBjg3pvH3SK To: "SOKAMLOOPS BC " <sip:2505555555@456.456.456.456>;tag=as755f2144 Call-ID: 3a3825c20a395c2f02a629bd22ef969c@456.456.456.456:5060 CSeq: 96873063 ACK Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:37:35.289629 [DEBUG] sofia.c:6963 Channel sofia/external/ 2505555555@456.456.456.456 entering state [terminated][481] 2016-09-20 17:37:35.289629 [NOTICE] sofia.c:8062 Hangup sofia/external/ 2505555555@456.456.456.456 [CS_RESET] [NORMAL_TEMPORARY_FAILURE] 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_HANGUP 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:809 (sofia/external/2505555555@456.456.456.456) Callstate Change ACTIVE -> HANGUP 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:811 (sofia/external/2505555555@456.456.456.456) State HANGUP 2016-09-20 17:37:35.289629 [DEBUG] mod_sofia.c:438 Channel sofia/external/ 2505555555@456.456.456.456 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:60 sofia/external/2505555555@456.456.456.456 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:811 (sofia/external/2505555555@456.456.456.456) State HANGUP going to sleep 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:742 Hangup Command with no Session lua(app.lua hangup): 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:578 (sofia/external/2505555555@456.456.456.456) State Change CS_HANGUP -> CS_REPORTING 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:543 (sofia/external/2505555555@456.456.456.456) Running State Change CS_REPORTING 2016-09-20 17:37:35.289629 [DEBUG] switch_core_state_machine.c:897 (sofia/external/2505555555@456.456.456.456) State REPORTING 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:174 sofia/external/2505555555@456.456.456.456 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:897 (sofia/external/2505555555@456.456.456.456) State REPORTING going to sleep 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:569 (sofia/external/2505555555@456.456.456.456) State Change CS_REPORTING -> CS_DESTROY 2016-09-20 17:37:35.329553 [DEBUG] switch_core_session.c:1647 Session 5 (sofia/external/2505555555@456.456.456.456) Locked, Waiting on external entities 2016-09-20 17:37:35.329553 [NOTICE] switch_core_session.c:1665 Session 5 (sofia/external/2505555555@456.456.456.456) Ended 2016-09-20 17:37:35.329553 [NOTICE] switch_core_session.c:1669 Close Channel sofia/external/2505555555@456.456.456.456 [CS_DESTROY] 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:700 (sofia/external/2505555555@456.456.456.456) Running State Change CS_DESTROY 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:710 (sofia/external/2505555555@456.456.456.456) State DESTROY 2016-09-20 17:37:35.329553 [DEBUG] mod_sofia.c:343 sofia/external/2505555555 @456.456.456.456 SOFIA DESTROY 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:181 sofia/external/2505555555@456.456.456.456 Standard DESTROY 2016-09-20 17:37:35.329553 [DEBUG] switch_core_state_machine.c:710 (sofia/external/2505555555@456.456.456.456) State DESTROY going to sleep recv 824 bytes from udp/[72.143.224.138]:20365 at 17:37:35.371629: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 123.123.123.123;rport=5060;branch=z9hG4bK0DU6aXj2FvHBp Via: SIP/2.0/UDP 123.123.123.123;rport=5060;branch=z9hG4bKvXKtj06r89vca Contact: <sip:2001@72.143.224.138:20365;transport=UDP> To: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;tag=14496d0a From: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com>;tag=vDHFU74UXyNmS Call-ID: 65dd6ddc-fa36-1234-b68d-1803730b83c5 CSeq: 96873063 INVITE Content-Type: application/sdp User-Agent: Zoiper rv2.8.6 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 25.171.247.182 s=Zoiper c=IN IP4 25.171.247.182 t=0 0 m=audio 54200 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ 2016-09-20 17:37:35.369573 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [completing][200] 2016-09-20 17:37:35.369573 [DEBUG] sofia.c:6973 Remote SDP: v=0 o=Zoiper 0 2 IN IP4 25.171.247.182 s=Zoiper c=IN IP4 25.171.247.182 t=0 0 m=audio 54200 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 send 446 bytes to udp/[72.143.224.138]:20365 at 17:37:35.373931: ------------------------------------------------------------------------ ACK sip:2001@72.143.224.138:20365;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123;rport;branch=z9hG4bK1pmZcr35c57XH Max-Forwards: 70 From: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com>;tag=vDHFU74UXyNmS To: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;tag=14496d0a Call-ID: 65dd6ddc-fa36-1234-b68d-1803730b83c5 CSeq: 96873063 ACK Contact: <sip:2001@123.123.123.123:5060> Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:37:35.369573 [DEBUG] sofia.c:6963 Channel sofia/internal/ 2001@72.143.224.138:20365 entering state [ready][200] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4336 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4281 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4197 Set telephone-event payload to 101@8000 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4542 Set telephone-event payload to 101@8000 2016-09-20 17:37:35.369573 [DEBUG] switch_core_media.c:4601 sofia/internal/ 2001@72.143.224.138:20365 Set 2833 dtmf send payload to 101 recv payload to 101 recv 804 bytes from udp/[72.143.224.138]:20365 at 17:37:56.351865: ------------------------------------------------------------------------ REGISTER sip:sipa.test.com;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- b9edf472a8bb6736;rport Max-Forwards: 70 Contact: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc> To: <sip:2001@sipa.test.com;transport=UDP> From: <sip:2001@sipa.test.com;transport=UDP>;tag=485b613a Call-ID: Zp_dAlhQHhOnxlCOqIOQSQ.. CSeq: 36 REGISTER Expires: 60 User-Agent: Zoiper rv2.8.6 Authorization: Digest username="2001",realm="sipa.test.com ",nonce="835df416-7f93-11e6-828d-059a9340be7a",uri="sip:sipa.test.com; transport=UDP",response="a871aaeeeb8e395bd25baa2bc35e1f85",cnonce=" b671a0e31b5669bb233523be0b0c5a2a",nc=00000002,qop=auth,algorithm=MD5 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:37:56.349627 [WARNING] sofia_reg.c:1791 SIP auth challenge (REGISTER) on sofia profile 'internal' for [2001@sipa.test.com] from ip 72.143.224.138 send 644 bytes to udp/[72.143.224.138]:20365 at 17:37:56.354596: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- b9edf472a8bb6736;rport=20365 From: <sip:2001@sipa.test.com;transport=UDP>;tag=485b613a To: <sip:2001@sipa.test.com;transport=UDP>;tag=XZrpgyy7gUc8m Call-ID: Zp_dAlhQHhOnxlCOqIOQSQ.. CSeq: 36 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces WWW-Authenticate: Digest realm="sipa.test.com", nonce="a3a0e382-7f93-11e6-8291-059a9340be7a", stale=true, algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ recv 804 bytes from udp/[72.143.224.138]:20365 at 17:37:56.403816: ------------------------------------------------------------------------ REGISTER sip:sipa.test.com;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- 2143d80bb83fa0aa;rport Max-Forwards: 70 Contact: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc> To: <sip:2001@sipa.test.com;transport=UDP> From: <sip:2001@sipa.test.com;transport=UDP>;tag=485b613a Call-ID: Zp_dAlhQHhOnxlCOqIOQSQ.. CSeq: 37 REGISTER Expires: 60 User-Agent: Zoiper rv2.8.6 Authorization: Digest username="2001",realm="sipa.test.com ",nonce="a3a0e382-7f93-11e6-8291-059a9340be7a",uri="sip:sipa.test.com; transport=UDP",response="0ee4450e941de381ecc6503656ab8a08",cnonce=" 577702d5d1c07839b64fecf4f308659f",nc=00000001,qop=auth,algorithm=MD5 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ send 623 bytes to udp/[72.143.224.138]:20365 at 17:37:56.410869: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- 2143d80bb83fa0aa;rport=20365 From: <sip:2001@sipa.test.com;transport=UDP>;tag=485b613a To: <sip:2001@sipa.test.com;transport=UDP>;tag=y8HFjSFBe42tg Call-ID: Zp_dAlhQHhOnxlCOqIOQSQ.. CSeq: 37 REGISTER Contact: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;expires=60 Date: Wed, 21 Sep 2016 00:37:56 GMT User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:37:56.449557 [DEBUG] switch_pgsql.c:415 Query (select 1, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch=0 group by read_flags union select 0, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch<>0 group by read_flags;) returned PGRES_FATAL_ERROR 2016-09-20 17:37:56.449557 [ERR] switch_core_sqldb.c:1178 ERR: [select 1, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch=0 group by read_flags union select 0, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch<>0 group by read_flags;] [ERROR: relation "voicemail_msgs" does not exist LINE 1: select 1, read_flags, count(read_epoch) from voicemail_msgs ... ^ ] 2016-09-20 17:37:56.449557 [ERR] switch_core_sqldb.c:1178 ERR: [select 1, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch=0 group by read_flags union select 0, read_flags, count(read_epoch) from voicemail_msgs where username='2001' and domain='sipa.test.com' and in_folder='inbox' and read_epoch<>0 group by read_flags;] [ERROR: relation "voicemail_msgs" does not exist LINE 1: select 1, read_flags, count(read_epoch) from voicemail_msgs ... ^ ] send 933 bytes to udp/[72.143.224.138]:20365 at 17:37:56.452249: ------------------------------------------------------------------------ NOTIFY sip:2001@72.143.224.138:20365;transport=UDP;rinstance=d85e769961280fbc SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123;rport;branch=z9hG4bK2ZDreKm99DygD Max-Forwards: 70 From: <sip:2001@123.123.123.123>;tag=ZHB8Km0eBDSDc To: <sip:2001@123.123.123.123> Call-ID: 7b0e4a51-fa36-1234-008f-1803730b8a29 CSeq: 96873074 NOTIFY Contact: <sip:mod_sofia@123.123.123.123:5060> User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: message-summary Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: terminated;reason=noresource Content-Type: application/simple-message-summary Content-Length: 74 Messages-Waiting: no Message-Account: sip:2001@sipa.test.com ------------------------------------------------------------------------ recv 342 bytes from udp/[72.143.224.138]:20365 at 17:37:56.495779: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 123.123.123.123;rport=5060;branch=z9hG4bK2ZDreKm99DygD Contact: <sip:25.171.247.182:32731> To: <sip:2001@123.123.123.123>;tag=78ac3037 From: <sip:2001@123.123.123.123>;tag=ZHB8Km0eBDSDc Call-ID: 7b0e4a51-fa36-1234-008f-1803730b8a29 CSeq: 96873074 NOTIFY User-Agent: Zoiper rv2.8.6 Content-Length: 0 ------------------------------------------------------------------------ recv 402 bytes from udp/[456.456.456.456]:5060 at 17:38:16.100468: ------------------------------------------------------------------------ BYE sip:7786962265@123.123.123.123:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 456.456.456.456:5060;branch=z9hG4bK0966e536;rport Max-Forwards: 70 From: "SOKAMLOOPS BC " <sip:2505555555@456.456.456.456>;tag=as755f2144 To: <sip:7786962265@123.123.123.123:5080>;tag=FgXZ7SQvN5XQF Call-ID: 3a3825c20a395c2f02a629bd22ef969c@456.456.456.456:5060 CSeq: 103 BYE User-Agent: Itelnetworks Content-Length: 0 ------------------------------------------------------------------------ send 481 bytes to udp/[456.456.456.456]:5060 at 17:38:16.100594: ------------------------------------------------------------------------ SIP/2.0 481 Call Does Not Exist Via: SIP/2.0/UDP 456.456.456.456:5060;branch=z9hG4bK0966e536;rport=5060 From: "SOKAMLOOPS BC " <sip:2505555555@456.456.456.456>;tag=as755f2144 To: <sip:7786962265@123.123.123.123:5080>;tag=FgXZ7SQvN5XQF Call-ID: 3a3825c20a395c2f02a629bd22ef969c@456.456.456.456:5060 CSeq: 103 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ recv 487 bytes from udp/[72.143.224.138]:20365 at 17:38:18.222019: ------------------------------------------------------------------------ BYE sip:2001@123.123.123.123:5060 SIP/2.0 Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- 4e026360bb72799f;rport Max-Forwards: 70 Contact: <sip:2001@72.143.224.138:20365;transport=UDP> To: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com>;tag=vDHFU74UXyNmS From: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;tag=14496d0a Call-ID: 65dd6ddc-fa36-1234-b68d-1803730b83c5 CSeq: 2 BYE User-Agent: Zoiper rv2.8.6 Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:38:18.209629 [NOTICE] sofia.c:1011 Hangup sofia/internal/ 2001@72.143.224.138:20365 [CS_RESET] [NORMAL_CLEARING] 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_HANGUP send 532 bytes to udp/[72.143.224.138]:20365 at 17:38:18.222838: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 72.143.224.138:20365;branch=z9hG4bK-524287-1--- 4e026360bb72799f;rport=20365 From: <sip:2001@72.143.224.138:20365;transport=UDP;rinstance= d85e769961280fbc>;tag=14496d0a To: "SOKAMLOOPS BC " <sip:2505555555@sipa.test.com>;tag=vDHFU74UXyNmS Call-ID: 65dd6ddc-fa36-1234-b68d-1803730b83c5 CSeq: 2 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2001@72.143.224.138:20365) Callstate Change DOWN -> HANGUP 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2001@72.143.224.138:20365) State HANGUP 2016-09-20 17:38:18.209629 [DEBUG] mod_sofia.c:432 sofia/internal/ 2001@72.143.224.138:20365 Overriding SIP cause 480 with 481 from the other leg 2016-09-20 17:38:18.209629 [DEBUG] mod_sofia.c:438 Channel sofia/internal/ 2001@72.143.224.138:20365 hanging up, cause: NORMAL_CLEARING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2001@72.143.224.138:20365 Standard HANGUP, cause: NORMAL_CLEARING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2001@72.143.224.138:20365) State HANGUP going to sleep 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2001@72.143.224.138:20365) State Change CS_HANGUP -> CS_REPORTING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_REPORTING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2001@72.143.224.138:20365) State REPORTING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2001@72.143.224.138:20365 Standard REPORTING, cause: NORMAL_CLEARING 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2001@72.143.224.138:20365) State REPORTING going to sleep 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2001@72.143.224.138:20365) State Change CS_REPORTING -> CS_DESTROY 2016-09-20 17:38:18.209629 [DEBUG] switch_core_session.c:1647 Session 6 (sofia/internal/2001@72.143.224.138:20365) Locked, Waiting on external entities 2016-09-20 17:38:18.209629 [NOTICE] switch_core_session.c:1665 Session 6 (sofia/internal/2001@72.143.224.138:20365) Ended 2016-09-20 17:38:18.209629 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/2001@72.143.224.138:20365 [CS_DESTROY] 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2001@72.143.224.138:20365) Running State Change CS_DESTROY 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2001@72.143.224.138:20365) State DESTROY 2016-09-20 17:38:18.209629 [DEBUG] mod_sofia.c:343 sofia/internal/ 2001@72.143.224.138:20365 SOFIA DESTROY 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2001@72.143.224.138:20365 Standard DESTROY 2016-09-20 17:38:18.209629 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2001@72.143.224.138:20365) State DESTROY going to sleep recv 579 bytes from udp/[789.789.789.789]:5060 at 17:38:23.084830: ------------------------------------------------------------------------ OPTIONS sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 789.789.789.789:5060;branch=z9hG4bK225c5987;rport Max-Forwards: 70 From: "Unknown" <sip:Unknown@789.789.789.789>;tag=as6a493bca To: <sip:123.123.123.123> Contact: <sip:Unknown@789.789.789.789:5060> Call-ID: 429157a261083a5c509facc67aa348df@789.789.789.789:5060 CSeq: 102 OPTIONS User-Agent: Itelnetworks Date: Wed, 21 Sep 2016 00:38:23 GMT Session-Expires: 7200 Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 ------------------------------------------------------------------------ send 555 bytes to udp/[789.789.789.789]:5060 at 17:38:23.085328: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 789.789.789.789:5060;branch=z9hG4bK225c5987;rport=5060 From: "Unknown" <sip:Unknown@789.789.789.789>;tag=as6a493bca To: <sip:123.123.123.123>;tag=3He4KBmtStScF Call-ID: 429157a261083a5c509facc67aa348df@789.789.789.789:5060 CSeq: 102 OPTIONS Contact: <sip:123.123.123.123:5080> User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 529 bytes from udp/[456.456.456.456]:5060 at 17:38:26.118048: ------------------------------------------------------------------------ OPTIONS sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 456.456.456.456:5060;branch=z9hG4bK1e72e437;rport Max-Forwards: 70 From: "Unknown" <sip:Unknown@456.456.456.456>;tag=as3e625c42 To: <sip:123.123.123.123> Contact: <sip:Unknown@456.456.456.456:5060> Call-ID: 3853daf95e839ae9006385ce4562951b@456.456.456.456:5060 CSeq: 102 OPTIONS User-Agent: Itelnetworks Date: Wed, 21 Sep 2016 00:38:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces Content-Length: 0 ------------------------------------------------------------------------ send 549 bytes to udp/[456.456.456.456]:5060 at 17:38:26.118375: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 456.456.456.456:5060;branch=z9hG4bK1e72e437;rport=5060 From: "Unknown" <sip:Unknown@456.456.456.456>;tag=as3e625c42 To: <sip:123.123.123.123>;tag=4t7vN64Xp3FZa Call-ID: 3853daf95e839ae9006385ce4562951b@456.456.456.456:5060 CSeq: 102 OPTIONS Contact: <sip:123.123.123.123:5080> User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ -- *Tanner Kerr* | Junior Developer / Support Technician | *iTel.com <http://www.itel.com/> * *1.888.899.4835 <1.888.899.4835> *(ext:1027)
Also why are you doing all these user_data calls? set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) call set_user ${destination_number}@${domain_name}, Much more optimal! /b On Thu, Sep 22, 2016 at 9:47 AM, Michael Jerris <mike@jerris.com> wrote:
Particularly for an issue like this, obfuscated logs are basically useless.
On Sep 21, 2016, at 1:04 PM, Tanner Kerr <tanner@itel.com> wrote:
below are the logs from server a and b ips and dns obfuscated.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- *Brian West* brian@freeswitch.org *Twitter: @FreeSWITCH , @briankwest* http://www.freeswitchbook.com (50% Discount using code FreeSwitch50) http://www.freeswitchcookbook.com (50% Discount using code FreeSwitch50) https://www.gofundme.com/freeswitch_ubuntu Got Bugs? Report them here <https://freeswitch.org/jira>! | Reddit: /r/freeswitch <https://www.reddit.com/r/freeswitch> *T:*+19184209001 | *F:*+19184209002 | *M:*+1918424WEST (9378) *iNUM:*+883 5100 1420 9001 | *ISN:*410*543 | *Skype:*briankwest
participants (3)
-
Brian West
-
Michael Jerris
-
Tanner Kerr