Apparently there is something else going on with the Nortel to FS exchange I keep getting this error code when the call is being processed 79 501 *SERVICE_NOT_IMPLEMENTED* service or option not implemented, unspecified [Q.850] This cause is used to report a service or option not implemented event only when no other cause in the service or option not implemented class applies. On Thu, Feb 27, 2014 at 2:42 PM, Joel White <joelewhite@gmail.com> wrote:

Thank you

On Thu, Feb 27, 2014 at 1:55 PM, DJB International <djbinter@gmail.com>wrote:

...

^(\d{5});(.*)$

$1 = 23673 $2 = phone-context=location.systemname

On Thu, Feb 27, 2014 at 10:34 AM, Joel E White <joelewhite@gmail.com>wrote:

...

Hi

I am wondering how I can strip the extra information being sent from the nortel and passing only digits along.

The string from nortel is

23673;phone-context=location.systemname

I have substituted the data with fictional information, but this is the gist of it

What I need freeswitch to do is remove everything after the 5 numbers

I have been unsuccessful in doing so using regex (probably because of my lack of knowledge on the subject)

I have been able to accomplish this using asterisk, then passing the data along to freeswitch

exten => _X.,Dial(SIP/${EXTEN:0:-33}@freeswitch

Can someone show me how to accomplish the same using regex and variables like $1?

Thank you, Joel

Sent from my iPad _________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

I did add a line to the public incoming xml that uses the Say command to repeat back what $1 variable is set to. I figured it might help me in debugging +OK log level debug [7] 2014-02-27 15:13:05.086534 [NOTICE] switch_channel.c:1050 New Channel sofia/external/23673 [910ede7a-9feb-11e3-9a55-09241ec9370d] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_NEW 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:7868 sofia/external/23673 receiving invite from 10.111.11.10:5060 version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [received][100] 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5824 Remote SDP: v=0 o=- 269323 1 IN IP4 10.111.11.10 s=- c=IN IP4 10.111.11.17 t=0 0 m=audio 5218 RTP/AVP 0 8 18 101 111 c=IN IP4 10.111.11.17 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:6071 (sofia/external/23673) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:434 (sofia/external/23673) State NEW 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:87 sofia/external/23673 SOFIA INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:127 (sofia/external/23673) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT going to sleep 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change DOWN -> RINGING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:05.106494 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365;phone-context=location.systemname in context public Dialplan: sofia/external/23673 parsing [public->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [public->outside_call] continue=true Dialplan: sofia/external/23673 Absolute Condition [outside_call] Dialplan: sofia/external/23673 Action set(outside_call=true) Dialplan: sofia/external/23673 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/23673 parsing [public->call_debug] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 parsing [public->public_extensions] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_extensions] destination_number(28365;phone-context=location.systemname) =~ /^([456][0-9][0-9][0-9]/d?)$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_mgw00_inbound] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_did_mgw00_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5})$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_nortel_inbound] continue=false Dialplan: sofia/external/23673 Regex (PASS) [public_did_nortel_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5});(.*)$/ break=on-false Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action say(en number iterated 28365) Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action set(domain_name=10.20.30.123) Dialplan: sofia/external/23673 Action transfer(28365 XML default) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(outside_call=true) 2014-02-27 15:13:05.106494 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [outside_call]=[true] EXECUTE sofia/external/23673 export(RFC2822_DATE=Thu, 27 Feb 2014 15:13:05 -0500) 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] EXECUTE sofia/external/23673 answer() 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3190 Set Codec sofia/external/23673 PCMU/8000 20 ms 160 samples 64000 bits 2014-02-27 15:13:05.106494 [DEBUG] switch_core_codec.c:111 sofia/external/23673 Original read codec set to PCMU:0 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5451 Set 2833 dtmf send/recv payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3449 AUDIO RTP [sofia/external/23673] 10.20.30.123 port 20854 -> 10.111.11.17 port 5218 codec: 0 ms: 20 2014-02-27 15:13:05.106494 [DEBUG] switch_rtp.c:2033 Starting timer [soft] 160 bytes per 20ms 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf send payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3722 Set 2833 dtmf receive payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3749 sofia/external/23673 Set rtp dtmf delay to 40 2014-02-27 15:13:05.106494 [NOTICE] sofia_glue.c:4360 Pre-Answer sofia/external/23673! 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3367 (sofia/external/23673) Callstate Change RINGING -> EARLY 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:866 Local SDP sofia/external/23673: v=0 o=FreeSWITCH 1393511131 1393511132 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 20854 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 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [completed][200] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [NOTICE] mod_dptools.c:1225 Channel [sofia/external/23673] has been answered 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3646 (sofia/external/23673) Callstate Change EARLY -> ACTIVE EXECUTE sofia/external/23673 say(en number iterated 28365) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.126485 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [ready][200] 2014-02-27 15:13:05.126485 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:05.226537 [DEBUG] switch_rtp.c:3749 Correct ip/port confirmed. 2014-02-27 15:13:07.666516 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/2.wav!digits/8.wav!digits/3.wav!digits/6.wav!digits/5.wav EXECUTE sofia/external/23673 sleep(1000) EXECUTE sofia/external/23673 set(domain_name=10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [domain_name]=[10.20.30.123] EXECUTE sofia/external/23673 transfer(28365 XML default) 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr.c:1832 (sofia/external/23673) State Change CS_EXECUTE -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [NOTICE] switch_ivr.c:1839 Transfer sofia/external/23673 to XML[28365@default] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change ACTIVE -> RINGING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:08.666549 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365 in context default Dialplan: sofia/external/23673 parsing [default->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [default->tod_example] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->tod_brevard] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_brevard] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->holiday_example] continue=true Dialplan: sofia/external/23673 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/23673 parsing [default->global-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [global-intercept] destination_number(28365) =~ /^886$/ break=on-false Dialplan: sofia/external/23673 parsing [default->group-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [group-intercept] destination_number(28365) =~ /^\*8$/ break=on-false Dialplan: sofia/external/23673 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [intercept-ext] destination_number(28365) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->redial] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [redial] destination_number(28365) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->global] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^779$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call_return] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call_return] destination_number(28365) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/23673 parsing [default->del-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [del-group] destination_number(28365) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->add-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [add-group] destination_number(28365) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-simo] destination_number(28365) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-order] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-order] destination_number(28365) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [extension-intercom] destination_number(28365) =~ /^8([456][0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_4_digit] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [Local_Extension_4_digit] destination_number(28365) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_5_digit] continue=false Dialplan: sofia/external/23673 Regex (PASS) [Local_Extension_5_digit] destination_number(28365) =~ /^(5[0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 Action export(dialed_extension=28365) Dialplan: sofia/external/23673 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/external/23673 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/external/23673 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/external/23673 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/external/23673 Action set(ringback=${us-ring}) Dialplan: sofia/external/23673 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/external/23673 Action set(call_timeout=30) Dialplan: sofia/external/23673 Action set(hangup_after_bridge=true) Dialplan: sofia/external/23673 Action set(continue_on_fail=true) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/23673 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2165 (sofia/external/23673) Callstate Change RINGING -> ACTIVE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 export(dialed_extension=28365) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [dialed_extension]=[28365] EXECUTE sofia/external/23673 bind_meta_app(1 b s execute_extension::dx XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/external/23673 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav EXECUTE sofia/external/23673 bind_meta_app(3 b s execute_extension::cf XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/external/23673 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/external/23673 set(ringback=%(2000,4000,440,480)) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/23673 set(transfer_ringback=local_stream://moh) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/external/23673 set(call_timeout=30) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [call_timeout]=[30] EXECUTE sofia/external/23673 set(hangup_after_bridge=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [hangup_after_bridge]=[true] EXECUTE sofia/external/23673 set(continue_on_fail=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [continue_on_fail]=[true] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-call_return/28365/23673;phone-context=location.systemname) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/28365/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 set(called_party_callgroup=techsupport) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/global/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 bridge(user/28365@10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [sip_invite_domain]=[10.20.30.123] 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [presence_id]=[28365@10.20.30.123] 2014-02-27 15:13:08.666549 [NOTICE] switch_channel.c:1050 New Channel sofia/internal/sip:28365@10.20.30.121 [93309eb4-9feb-11e3-9a76-09241ec9370d] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5230 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5300 [zrtp_passthru] Setting a-leg inherit_codec=true 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5303 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b' 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:87 sofia/internal/ sip:28365@10.20.30.121 SOFIA INIT 2014-02-27 15:13:08.666549 [DEBUG] sofia_glue.c:2744 sofia/internal/ sip:28365@10.20.30.121 sending invite version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit Local SDP: v=0 o=FreeSWITCH 1393508912 1393508913 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 23076 RTP/AVP 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:127 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [calling][0] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/internal/ sip:28365@10.20.30.121 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:28365@10.20.30.121) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [terminated][415] 2014-02-27 15:13:08.686500 [NOTICE] sofia.c:6655 Hangup sofia/internal/ sip:28365@10.20.30.121 [CS_CONSUME_MEDIA] [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.686500 [DEBUG] switch_channel.c:3186 Send signal sofia/internal/sip:28365@10.20.30.121 [KILL] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/sip:28365@10.20.30.121) Callstate Change DOWN -> HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP 2014-02-27 15:13:08.686500 [DEBUG] mod_sofia.c:506 Channel sofia/internal/ sip:28365@10.20.30.121 hanging up, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:28365@10.20.30.121 Standard HANGUP, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/sip:28365@10.20.30.121) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:28365@10.20.30.121 Standard REPORTING, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/sip:28365@10.20.30.121) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1559 Session 2 (sofia/internal/sip:28365@10.20.30.121) Locked, Waiting on external entities 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:08.706527 [NOTICE] switch_ivr_originate.c:2670 Cannot create outgoing channel of type [user] cause: [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [INFO] mod_dptools.c:3201 Originate Failed. Cause: SERVICE_NOT_IMPLEMENTED EXECUTE sofia/external/23673 answer() EXECUTE sofia/external/23673 sleep(1000) 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1577 Session 2 (sofia/internal/sip:28365@10.20.30.121) Ended 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/sip:28365@10.20.30.121 [CS_DESTROY] 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/sip:28365@10.20.30.121) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY 2014-02-27 15:13:08.706527 [DEBUG] mod_sofia.c:399 sofia/internal/ sip:28365@10.20.30.121 SOFIA DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:28365@10.20.30.121 Standard DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY going to sleep EXECUTE sofia/external/23673 bridge(loopback/app=voicemail:default 10.20.30.123 28365) 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/app=voicemail:default 10.20.30.123 28365-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 10.20.30.123 28365-a setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1048 Rename Channel loopback/app=voicemail:default 10.20.30.123 28365-a->loopback/voicemail-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:1158 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/voicemail-b [93cd7874-9feb-11e3-9a83-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:272 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-a CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:648 CHANNEL CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:2163 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-b CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:408 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:431 loopback/voicemail-b CHANNEL EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:209 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2014-02-27 15:13:09.706545 [NOTICE] mod_loopback.c:945 Pre-Answer loopback/voicemail-a! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3363 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 10.20.30.123 28365) 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_originate.c:3513 Originate Resulted in Success: [loopback/voicemail-a] 2014-02-27 15:13:09.726502 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_bridge.c:1429 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:610 CHANNEL LOOPBACK 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:11.206539 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:251 Handle say:[28365] (en:en) 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:13.866518 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/5.wav!digits/7.wav!digits/3.wav!digits/3.wav!digits/1.wav 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:14.946549 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:15.646531 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] sofia.c:737 Hangup sofia/external/23673 [CS_EXECUTE] [NORMAL_CLEARING] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal sofia/external/23673 [KILL] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/external/23673] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:557 sofia/external/23673 ending bridge by request from write function 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [loopback/voicemail-a] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] switch_ivr_bridge.c:722 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-a [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:535 loopback/voicemail-a CHANNEL HANGUP 2014-02-27 15:13:15.666534 [NOTICE] mod_loopback.c:551 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-b [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 3 (loopback/voicemail-a) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:1530 sofia/external/23673 skip receive message [UNBRIDGE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:2810 sofia/external/23673 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (sofia/external/23673) Callstate Change ACTIVE -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:500 sofia/external/23673 Overriding SIP cause 480 with 415 from the other leg 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:506 Channel sofia/external/23673 hanging up, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 sofia/external/23673 Standard HANGUP, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (sofia/external/23673) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 sofia/external/23673 Standard REPORTING, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (sofia/external/23673) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 1 (sofia/external/23673) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1577 Session 1 (sofia/external/23673) Ended 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1581 Close Channel sofia/external/23673 [CS_DESTROY] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:566 (sofia/external/23673) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:569 (sofia/external/23673) Running State Change CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:399 sofia/external/23673 SOFIA DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:99 sofia/external/23673 Standard DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:2810 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:535 loopback/voicemail-b CHANNEL HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1559 Session 4 (loopback/voicemail-b) Locked, Waiting on external entities 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 4 (loopback/voicemail-b) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-b [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-b) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-b Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 3 (loopback/voicemail-a) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-a [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-a) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-a Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY going to sleep

Here is the Siptrace coming from the Nortel to FS +OK log level console [0] freeswitch@internal> sofia global siptrace on +OK Global siptrace on recv 2230 bytes from udp/[10.20.30.121]:5060 at 13:40:16.646438: ------------------------------------------------------------------------ INVITE sip:57331;phone-context=location.systemname@sip.nortel.net:5080;maddr=10.20.30.123;transport=udp;user=phone;x-nt-redirect=redirect-server SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone> Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 P-Asserted-Identity: <sip:52321;phone-context= location.systemname@sip.nortel.net;user=phone> Privacy: none History-Info: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;index=1 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: multipart/mixed;boundary=unique-boundary-1 Content-Length: 1008 --unique-boundary-1 Content-Type: application/sdp v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv --unique-boundary-1 Content-Type: application/x-nt-mcdn-frag-hex;version=ssLinux-7.00.20;base=x2611 Content-Disposition: signal;handling=optional 05000002 0107130081900000a200 09090f00e9a0830001008000 1315070011fa0f00a10d02010102020100cc040000754a00 1e0403008183 460e01000a0001000100010000000000 4a1c01001800010000000000000023617137990004000000000025230100 --unique-boundary-1 Content-Type: application/x-nt-esn5-frag-hex Content-Disposition: signal;handling=optional 103 --unique-boundary-1 Content-Type: application/x-nt-epid-frag-hex;version=ssLinux-7.00.20;base=x2611 Content-Disposition: signal;handling=optional 011201 80:17:7d:4e:b2:38 --unique-boundary-1-- ------------------------------------------------------------------------ send 490 bytes to udp/[10.20.30.121]:5060 at 13:40:16.647161: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone> Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Content-Length: 0 ------------------------------------------------------------------------ send 1207 bytes to udp/[10.20.30.121]:5060 at 13:40:16.654280: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE Contact: <sip:57331;phone-context=location.systemname@10.20.30.123:5080 ;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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-Type: application/sdp Content-Disposition: session Content-Length: 222 P-Asserted-Identity: "57331;phone-context=location.systemname" <sip:57331;phone-context=location.systemname@sip.nortel.net> v=0 o=FreeSWITCH 1393568474 1393568475 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 26342 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 855 bytes from udp/[10.20.30.121]:5060 at 13:40:16.657553: ------------------------------------------------------------------------ ACK sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 ACK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1d3-5012ca8a Max-Forwards: 70 User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0 ------------------------------------------------------------------------ recv 905 bytes from udp/[10.20.30.121]:5060 at 13:40:16.658829: ------------------------------------------------------------------------ OPTIONS sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 2 OPTIONS Via: SIP/2.0/UDP 10.20.30.121:5060;branch=z9hG4bK-aed5f0-aaf3b1d5-82ef650 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0 ------------------------------------------------------------------------ send 1041 bytes to udp/[10.20.30.121]:5060 at 13:40:16.674438: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060;branch=z9hG4bK-aed5f0-aaf3b1d5-82ef650 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 2 OPTIONS Contact: <sip:57331;phone-context=location.systemname@10.20.30.123:5080 ;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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-Type: application/sdp Content-Length: 218 v=0 o=FreeSWITCH 1393568474 1393568475 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 0 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ send 2373 bytes to udp/[10.20.30.151]:5060 at 13:40:20.244041: ------------------------------------------------------------------------ INVITE sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm Max-Forwards: 68 From: "52321;phone-context=location.systemname" <sip:52321;phone-context= location.systemname@10.20.30.123>;tag=K8vUtjFrQUjtg To: <sip:57331@10.20.30.151> Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea CSeq: 56461346 INVITE Contact: <sip:mod_sofia@10.20.30.123:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Privacy: none Content-Type: multipart/mixed;boundary=ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Length: 1250 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 X-FS-Support: update_display,send_info P-Asserted-Identity: "52321;phone-context=location.systemname" <sip:52321;phone-context=location.systemname@10.20.30.123> --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/sdp Content-Length: 262 v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-mcdn-frag-hex Content-Length: 217 05000002 0107130081900000a200 09090f00e9a0830001008000 1315070011fa0f00a10d02010102020100cc040000754a00 1e0403008183 460e01000a0001000100010000000000 4a1c01001800010000000000000023617137990004000000000025230100 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-esn5-frag-hex Content-Length: 4 103 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-epid-frag-hex Content-Length: 26 011201 80:17:7d:4e:b2:38 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/sdp Content-Length: 208 v=0 o=FreeSWITCH 1393575650 1393575651 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 19170 RTP/AVP 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --ddb7d988-a07d-11e3-9b14-09241ec9370d-- ------------------------------------------------------------------------ recv 506 bytes from udp/[10.20.30.151]:5060 at 13:40:20.257663: ------------------------------------------------------------------------ SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm From: "52321;phone-context=location.systemname" <sip:52321;phone-context= location.systemname@10.20.30.123>;tag=K8vUtjFrQUjtg To: "Joel White" <sip:57331@10.20.30.151>;tag=AC57CD1-9FDEC368 CSeq: 56461346 INVITE Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Accept-Language: en Content-Length: 0 ------------------------------------------------------------------------ send 409 bytes to udp/[10.20.30.151]:5060 at 13:40:20.257909: ------------------------------------------------------------------------ ACK sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm Max-Forwards: 68 From: "52321;phone-context=location.systemname" <sip:52321;phone-context= location.systemname@10.20.30.123>;tag=K8vUtjFrQUjtg To: "Joel White" <sip:57331@10.20.30.151>;tag=AC57CD1-9FDEC368 Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea CSeq: 56461346 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 1068 bytes from udp/[10.20.30.121]:5060 at 13:40:28.637828: ------------------------------------------------------------------------ BYE sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 3 BYE Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5fc-aaf3e09e-75565f26 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: application/sdp Content-Length: 261 v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ send 625 bytes to udp/[10.20.30.121]:5060 at 13:40:28.648789: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5fc-aaf3e09e-75565f26 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 3 BYE User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ On Thu, Feb 27, 2014 at 3:42 PM, Brian West <brian@freeswitch.org> wrote:

sofia global siptrace on

That will help me a little more.

-- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com

T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)

On Feb 27, 2014, at 2:23 PM, Joel White <joelewhite@gmail.com> wrote:

...

I did add a line to the public incoming xml that uses the Say command to repeat back what $1 variable is set to. I figured it might help me in debugging

+OK log level debug [7] 2014-02-27 15:13:05.086534 [NOTICE] switch_channel.c:1050 New Channel sofia/external/23673 [910ede7a-9feb-11e3-9a55-09241ec9370d] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_NEW 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:7868 sofia/external/23673 receiving invite from 10.111.11.10:5060 version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [received][100] 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5824 Remote SDP: v=0 o=- 269323 1 IN IP4 10.111.11.10 s=- c=IN IP4 10.111.11.17 t=0 0 m=audio 5218 RTP/AVP 0 8 18 101 111 c=IN IP4 10.111.11.17 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20

2014-02-27 15:13:05.086534 [DEBUG] sofia.c:6071 (sofia/external/23673) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:434 (sofia/external/23673) State NEW 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:87 sofia/external/23673 SOFIA INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:127 (sofia/external/23673) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT going to sleep 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change DOWN -> RINGING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:05.106494 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365;phone-context=location.systemname in context public Dialplan: sofia/external/23673 parsing [public->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [public->outside_call] continue=true Dialplan: sofia/external/23673 Absolute Condition [outside_call] Dialplan: sofia/external/23673 Action set(outside_call=true) Dialplan: sofia/external/23673 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/23673 parsing [public->call_debug] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 parsing [public->public_extensions] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_extensions] destination_number(28365;phone-context=location.systemname) =~ /^([456][0-9][0-9][0-9]/d?)$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_mgw00_inbound] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_did_mgw00_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5})$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_nortel_inbound] continue=false Dialplan: sofia/external/23673 Regex (PASS) [public_did_nortel_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5});(.*)$/ break=on-false Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action say(en number iterated 28365) Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action set(domain_name=10.20.30.123) Dialplan: sofia/external/23673 Action transfer(28365 XML default) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(outside_call=true) 2014-02-27 15:13:05.106494 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [outside_call]=[true] EXECUTE sofia/external/23673 export(RFC2822_DATE=Thu, 27 Feb 2014 15:13:05 -0500) 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] EXECUTE sofia/external/23673 answer() 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3190 Set Codec sofia/external/23673 PCMU/8000 20 ms 160 samples 64000 bits 2014-02-27 15:13:05.106494 [DEBUG] switch_core_codec.c:111 sofia/external/23673 Original read codec set to PCMU:0 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5451 Set 2833 dtmf send/recv payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3449 AUDIO RTP [sofia/external/23673] 10.20.30.123 port 20854 -> 10.111.11.17 port 5218 codec: 0 ms: 20 2014-02-27 15:13:05.106494 [DEBUG] switch_rtp.c:2033 Starting timer [soft] 160 bytes per 20ms 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf send payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3722 Set 2833 dtmf receive payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3749 sofia/external/23673 Set rtp dtmf delay to 40 2014-02-27 15:13:05.106494 [NOTICE] sofia_glue.c:4360 Pre-Answer sofia/external/23673! 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3367 (sofia/external/23673) Callstate Change RINGING -> EARLY 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:866 Local SDP sofia/external/23673: v=0 o=FreeSWITCH 1393511131 1393511132 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 20854 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

2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [completed][200] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [NOTICE] mod_dptools.c:1225 Channel [sofia/external/23673] has been answered 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3646 (sofia/external/23673) Callstate Change EARLY -> ACTIVE EXECUTE sofia/external/23673 say(en number iterated 28365) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.126485 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [ready][200] 2014-02-27 15:13:05.126485 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:05.226537 [DEBUG] switch_rtp.c:3749 Correct ip/port confirmed. 2014-02-27 15:13:07.666516 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/2.wav!digits/8.wav!digits/3.wav!digits/6.wav!digits/5.wav EXECUTE sofia/external/23673 sleep(1000) EXECUTE sofia/external/23673 set(domain_name=10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [domain_name]=[10.20.30.123] EXECUTE sofia/external/23673 transfer(28365 XML default) 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr.c:1832 (sofia/external/23673) State Change CS_EXECUTE -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [NOTICE] switch_ivr.c:1839 Transfer sofia/external/23673 to XML[28365@default] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change ACTIVE -> RINGING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:08.666549 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365 in context default Dialplan: sofia/external/23673 parsing [default->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [default->tod_example] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->tod_brevard] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_brevard] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->holiday_example] continue=true Dialplan: sofia/external/23673 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/23673 parsing [default->global-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [global-intercept] destination_number(28365) =~ /^886$/ break=on-false Dialplan: sofia/external/23673 parsing [default->group-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [group-intercept] destination_number(28365) =~ /^\*8$/ break=on-false Dialplan: sofia/external/23673 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [intercept-ext] destination_number(28365) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->redial] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [redial] destination_number(28365) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->global] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^779$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call_return] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call_return] destination_number(28365) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/23673 parsing [default->del-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [del-group] destination_number(28365) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->add-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [add-group] destination_number(28365) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-simo] destination_number(28365) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-order] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-order] destination_number(28365) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [extension-intercom] destination_number(28365) =~ /^8([456][0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_4_digit] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [Local_Extension_4_digit] destination_number(28365) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_5_digit] continue=false Dialplan: sofia/external/23673 Regex (PASS) [Local_Extension_5_digit] destination_number(28365) =~ /^(5[0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 Action export(dialed_extension=28365) Dialplan: sofia/external/23673 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/external/23673 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/external/23673 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/external/23673 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/external/23673 Action set(ringback=${us-ring}) Dialplan: sofia/external/23673 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/external/23673 Action set(call_timeout=30) Dialplan: sofia/external/23673 Action set(hangup_after_bridge=true) Dialplan: sofia/external/23673 Action set(continue_on_fail=true) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/23673 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action bridge(user/${dialed_extension}@ ${domain_name}) Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2165 (sofia/external/23673) Callstate Change RINGING -> ACTIVE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 export(dialed_extension=28365) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [dialed_extension]=[28365] EXECUTE sofia/external/23673 bind_meta_app(1 b s execute_extension::dx XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/external/23673 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav EXECUTE sofia/external/23673 bind_meta_app(3 b s execute_extension::cf XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/external/23673 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/external/23673 set(ringback=%(2000,4000,440,480)) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/23673 set(transfer_ringback=local_stream://moh) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/external/23673 set(call_timeout=30) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [call_timeout]=[30] EXECUTE sofia/external/23673 set(hangup_after_bridge=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [hangup_after_bridge]=[true] EXECUTE sofia/external/23673 set(continue_on_fail=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [continue_on_fail]=[true] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-call_return/28365/23673;phone-context=location.systemname) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/28365/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 set(called_party_callgroup=techsupport) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/global/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 bridge(user/28365@10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [sip_invite_domain]=[10.20.30.123] 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [presence_id]=[28365@10.20.30.123] 2014-02-27 15:13:08.666549 [NOTICE] switch_channel.c:1050 New Channel sofia/internal/sip:28365@10.20.30.121[93309eb4-9feb-11e3-9a76-09241ec9370d] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5230 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5300 [zrtp_passthru] Setting a-leg inherit_codec=true 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5303 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMU@8000h@20i@64000b,PCMA@8000h @20i@64000b' 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:87 sofia/internal/ sip:28365@10.20.30.121 SOFIA INIT 2014-02-27 15:13:08.666549 [DEBUG] sofia_glue.c:2744 sofia/internal/ sip:28365@10.20.30.121 sending invite version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit Local SDP: v=0 o=FreeSWITCH 1393508912 1393508913 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 23076 RTP/AVP 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv

2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:127 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [calling][0] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/internal/ sip:28365@10.20.30.121 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:28365@10.20.30.121) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [terminated][415] 2014-02-27 15:13:08.686500 [NOTICE] sofia.c:6655 Hangup sofia/internal/ sip:28365@10.20.30.121 [CS_CONSUME_MEDIA] [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.686500 [DEBUG] switch_channel.c:3186 Send signal sofia/internal/sip:28365@10.20.30.121 [KILL] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/sip:28365@10.20.30.121) Callstate Change DOWN -> HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP 2014-02-27 15:13:08.686500 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:28365@10.20.30.121 hanging up, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:28365@10.20.30.121 Standard HANGUP, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/sip:28365@10.20.30.121) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:28365@10.20.30.121 Standard REPORTING, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/sip:28365@10.20.30.121) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1559 Session 2 (sofia/internal/sip:28365@10.20.30.121) Locked, Waiting on external entities 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:08.706527 [NOTICE] switch_ivr_originate.c:2670 Cannot create outgoing channel of type [user] cause: [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [INFO] mod_dptools.c:3201 Originate Failed. Cause: SERVICE_NOT_IMPLEMENTED EXECUTE sofia/external/23673 answer() EXECUTE sofia/external/23673 sleep(1000) 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1577 Session 2 (sofia/internal/sip:28365@10.20.30.121) Ended 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/sip:28365@10.20.30.121 [CS_DESTROY] 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/sip:28365@10.20.30.121) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY 2014-02-27 15:13:08.706527 [DEBUG] mod_sofia.c:399 sofia/internal/ sip:28365@10.20.30.121 SOFIA DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:28365@10.20.30.121 Standard DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY going to sleep EXECUTE sofia/external/23673 bridge(loopback/app=voicemail:default 10.20.30.123 28365) 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/app=voicemail:default 10.20.30.123 28365-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 10.20.30.123 28365-a setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1048 Rename Channel loopback/app=voicemail:default 10.20.30.123 28365-a->loopback/voicemail-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:1158 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/voicemail-b [93cd7874-9feb-11e3-9a83-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:272 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-a CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:648 CHANNEL CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:2163 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-b CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:408 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:431 loopback/voicemail-b CHANNEL EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:209 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2014-02-27 15:13:09.706545 [NOTICE] mod_loopback.c:945 Pre-Answer loopback/voicemail-a! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3363 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 10.20.30.123 28365) 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_originate.c:3513 Originate Resulted in Success: [loopback/voicemail-a] 2014-02-27 15:13:09.726502 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_bridge.c:1429 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:610 CHANNEL LOOPBACK 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:11.206539 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:251 Handle say:[28365] (en:en) 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:13.866518 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/5.wav!digits/7.wav!digits/3.wav!digits/3.wav!digits/1.wav 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:14.946549 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:15.646531 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] sofia.c:737 Hangup sofia/external/23673 [CS_EXECUTE] [NORMAL_CLEARING] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal sofia/external/23673 [KILL] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/external/23673] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:557 sofia/external/23673 ending bridge by request from write function 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [loopback/voicemail-a] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] switch_ivr_bridge.c:722 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-a [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:535 loopback/voicemail-a CHANNEL HANGUP 2014-02-27 15:13:15.666534 [NOTICE] mod_loopback.c:551 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-b [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 3 (loopback/voicemail-a) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:1530 sofia/external/23673 skip receive message [UNBRIDGE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:2810 sofia/external/23673 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (sofia/external/23673) Callstate Change ACTIVE -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:500 sofia/external/23673 Overriding SIP cause 480 with 415 from the other leg 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:506 Channel sofia/external/23673 hanging up, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 sofia/external/23673 Standard HANGUP, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (sofia/external/23673) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 sofia/external/23673 Standard REPORTING, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (sofia/external/23673) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 1 (sofia/external/23673) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1577 Session 1 (sofia/external/23673) Ended 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1581 Close Channel sofia/external/23673 [CS_DESTROY] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:566 (sofia/external/23673) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:569 (sofia/external/23673) Running State Change CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:399 sofia/external/23673 SOFIA DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:99 sofia/external/23673 Standard DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:2810 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:535 loopback/voicemail-b CHANNEL HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1559 Session 4 (loopback/voicemail-b) Locked, Waiting on external entities 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 4 (loopback/voicemail-b) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-b [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-b) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-b Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 3 (loopback/voicemail-a) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-a [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-a) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-a Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY going to sleep

_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

Try <action application="set" data="sip_copy_multipart=false"/> On Fri, Feb 28, 2014 at 6:13 AM, Joel White <joelewhite@gmail.com> wrote:

Here is the Siptrace From the Asterisk (Stripping the extra characters before the @ ) to the FS

freeswitch@internal> sofia global siptrace on +OK Global siptrace on recv 834 bytes from udp/[10.20.30.140]:5060 at 13:51:07.042727: ------------------------------------------------------------------------ INVITE sip:57331@10.20.30.123:5080 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK71ed3030 Max-Forwards: 70 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080> Contact: <sip:52321@10.20.30.140:5060> Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.13.1~dfsg1-3+deb7u3 Date: Fri, 28 Feb 2014 13:51:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 250

v=0 o=root 262113027 262113027 IN IP4 10.20.30.140 s=Asterisk PBX 1.8.13.1~dfsg1-3+deb7u3 c=IN IP4 10.20.30.140 t=0 0 m=audio 11924 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 ------------------------------------------------------------------------ send 349 bytes to udp/[10.20.30.140]:5060 at 13:51:07.043438: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK71ed3030 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080> Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 102 INVITE

User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Content-Length: 0

------------------------------------------------------------------------ send 985 bytes to udp/[10.20.30.140]:5060 at 13:51:07.050345: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK71ed3030 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080>;tag=4eBX30941mX7Q Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 102 INVITE Contact: <sip:57331@10.20.30.123:5080;transport=udp>

User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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-Type: application/sdp Content-Disposition: session Content-Length: 222 Remote-Party-ID: "57331" <sip:57331@10.20.30.123

...

;party=calling;privacy=off;screen=no

v=0 o=FreeSWITCH 1393576015 1393576016 IN IP4 10.20.30.123

s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 19452 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 429 bytes from udp/[10.20.30.140]:5060 at 13:51:07.051392: ------------------------------------------------------------------------ ACK sip:57331@10.20.30.123:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK5cc9b7f1 Max-Forwards: 70 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080>;tag=4eBX30941mX7Q Contact: <sip:52321@10.20.30.140:5060> Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.13.1~dfsg1-3+deb7u3 Content-Length: 0

------------------------------------------------------------------------ send 1123 bytes to udp/[10.20.30.151]:5060 at 13:51:10.622223:

------------------------------------------------------------------------ INVITE sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p Max-Forwards: 68 From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: <sip:57331@10.20.30.151> Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea CSeq: 56461671 INVITE

Contact: <sip:mod_sofia@10.20.30.123:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 203 X-FS-Support: update_display,send_info Remote-Party-ID: "52321" <sip:52321@10.20.30.123

...

;party=calling;screen=yes;privacy=off

v=0 o=FreeSWITCH 1393572016 1393572017 IN IP4 10.20.30.123

s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 23454 RTP/AVP 0 101 13

a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 417 bytes from udp/[10.20.30.151]:5060 at 13:51:10.631809: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: "Joel White" <sip:57331@10.20.30.151>;tag=DBC84228-8FD7AFC7 CSeq: 56461671 INVITE Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea

Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Accept-Language: en Content-Length: 0

------------------------------------------------------------------------ recv 454 bytes from udp/[10.20.30.151]:5060 at 13:51:10.703141: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: "Joel White" <sip:57331@10.20.30.151>;tag=DBC84228-8FD7AFC7 CSeq: 56461671 INVITE Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea

Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Allow-Events: talk,hold,conference

Accept-Language: en Content-Length: 0

------------------------------------------------------------------------ recv 462 bytes from udp/[10.20.30.140]:5060 at 13:51:17.335771: ------------------------------------------------------------------------ BYE sip:57331@10.20.30.123:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK5a3cf3d8 Max-Forwards: 70 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080>;tag=4eBX30941mX7Q Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 103 BYE User-Agent: Asterisk PBX 1.8.13.1~dfsg1-3+deb7u3 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0

------------------------------------------------------------------------ send 484 bytes to udp/[10.20.30.140]:5060 at 13:51:17.348404: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK5a3cf3d8 From: "52321" <sip:52321@10.20.30.140>;tag=as78102a82 To: <sip:57331@10.20.30.123:5080>;tag=4eBX30941mX7Q Call-ID: 601f874e379507e644893ee939a29315@10.20.30.140:5060 CSeq: 103 BYE

User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0

------------------------------------------------------------------------ send 428 bytes to udp/[10.20.30.151]:5060 at 13:51:17.353751: ------------------------------------------------------------------------ CANCEL sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p Max-Forwards: 68 From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: <sip:57331@10.20.30.151> Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea CSeq: 56461671 CANCEL Reason: SIP;cause=487;text="ORIGINATOR_CANCEL" Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16

------------------------------------------------------------------------ recv 391 bytes from udp/[10.20.30.151]:5060 at 13:51:17.359753: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm

To: "Joel White" <sip:57331@10.20.30.151> CSeq: 56461671 CANCEL Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea

Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Accept-Language: en Content-Length: 0

------------------------------------------------------------------------ recv 428 bytes from udp/[10.20.30.151]:5060 at 13:51:17.362819: ------------------------------------------------------------------------ SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: "Joel White" <sip:57331@10.20.30.151>;tag=DBC84228-8FD7AFC7 CSeq: 56461671 INVITE Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea

Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Accept-Language: en Content-Length: 0

------------------------------------------------------------------------ send 336 bytes to udp/[10.20.30.151]:5060 at 13:51:17.363074:

------------------------------------------------------------------------ ACK sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKvmFyHKHH6FD7p Max-Forwards: 68 From: "52321" <sip:52321@10.20.30.123>;tag=X2SKc1QUtmHNm To: "Joel White" <sip:57331@10.20.30.151>;tag=DBC84228-8FD7AFC7 Call-ID: 38be43c7-1b22-1232-d8b6-d243871458ea CSeq: 56461671 ACK Content-Length: 0

------------------------------------------------------------------------ recv 540 bytes from udp/[10.20.30.140]:5060 at 13:51:29.477899: ------------------------------------------------------------------------ OPTIONS sip:10.20.30.123 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK3a2e0e2e Max-Forwards: 70 From: "asterisk" <sip:asterisk@10.20.30.140>;tag=as6211ed46 To: <sip:10.20.30.123> Contact: <sip:asterisk@10.20.30.140:5060> Call-ID: 120e2bb047c767435da235fe4869e8d8@10.20.30.140:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.13.1~dfsg1-3+deb7u3 Date: Fri, 28 Feb 2014 13:51:32 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0

------------------------------------------------------------------------ send 588 bytes to udp/[10.20.30.140]:5060 at 13:51:29.478511: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.140:5060;branch=z9hG4bK3a2e0e2e From: "asterisk" <sip:asterisk@10.20.30.140>;tag=as6211ed46 To: <sip:10.20.30.123>;tag=5Q4N5Ut8yXKtK Call-ID: 120e2bb047c767435da235fe4869e8d8@10.20.30.140:5060 CSeq: 102 OPTIONS Contact: <sip:10.20.30.123:5080>

User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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

------------------------------------------------------------------------

On Fri, Feb 28, 2014 at 9:11 AM, Joel White <joelewhite@gmail.com> wrote:

...

Here is the Siptrace coming from the Nortel to FS

+OK log level console [0] freeswitch@internal> sofia global siptrace on +OK Global siptrace on recv 2230 bytes from udp/[10.20.30.121]:5060 at 13:40:16.646438:

------------------------------------------------------------------------ INVITE sip:57331;phone-context=location.systemname@sip.nortel.net:5080;maddr=10.20.30.123;transport=udp;user=phone;x-nt-redirect=redirect-server SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone> Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 P-Asserted-Identity: <sip:52321;phone-context= location.systemname@sip.nortel.net;user=phone> Privacy: none History-Info: <sip:57331;phone-context= location.systemname@sip.nortel.net;user=phone>;index=1 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: multipart/mixed;boundary=unique-boundary-1 Content-Length: 1008

--unique-boundary-1 Content-Type: application/sdp

v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122

a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv

--unique-boundary-1 Content-Type: application/x-nt-mcdn-frag-hex;version=ssLinux-7.00.20;base=x2611 Content-Disposition: signal;handling=optional

05000002 0107130081900000a200 09090f00e9a0830001008000 1315070011fa0f00a10d02010102020100cc040000754a00 1e0403008183 460e01000a0001000100010000000000 4a1c01001800010000000000000023617137990004000000000025230100 --unique-boundary-1 Content-Type: application/x-nt-esn5-frag-hex Content-Disposition: signal;handling=optional

103 --unique-boundary-1 Content-Type: application/x-nt-epid-frag-hex;version=ssLinux-7.00.20;base=x2611 Content-Disposition: signal;handling=optional

011201 80:17:7d:4e:b2:38 --unique-boundary-1--

------------------------------------------------------------------------ send 490 bytes to udp/[10.20.30.121]:5060 at 13:40:16.647161:

------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone> Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Content-Length: 0

------------------------------------------------------------------------ send 1207 bytes to udp/[10.20.30.121]:5060 at 13:40:16.654280:

------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1c7-6e065518 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 INVITE Contact: <sip:57331;phone-context=location.systemname@10.20.30.123:5080 ;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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-Type: application/sdp Content-Disposition: session Content-Length: 222 P-Asserted-Identity: "57331;phone-context=location.systemname" <sip:57331;phone-context=location.systemname@sip.nortel.net>

v=0 o=FreeSWITCH 1393568474 1393568475 IN IP4 10.20.30.123

s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 26342 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20

------------------------------------------------------------------------ recv 855 bytes from udp/[10.20.30.121]:5060 at 13:40:16.657553:

------------------------------------------------------------------------ ACK sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 1 ACK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1d3-5012ca8a Max-Forwards: 70 User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0

------------------------------------------------------------------------ recv 905 bytes from udp/[10.20.30.121]:5060 at 13:40:16.658829:

------------------------------------------------------------------------ OPTIONS sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 2 OPTIONS Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1d5-82ef650 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Contact: <sip:52321;phone-context=location.systemname@sip.nortel.net:5060 ;maddr=10.20.30.121;transport=udp;user=phone> Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0

------------------------------------------------------------------------ send 1041 bytes to udp/[10.20.30.121]:5060 at 13:40:16.674438:

------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5f0-aaf3b1d5-82ef650 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 2 OPTIONS Contact: <sip:57331;phone-context=location.systemname@10.20.30.123:5080 ;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit 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-Type: application/sdp Content-Length: 218

v=0 o=FreeSWITCH 1393568474 1393568475 IN IP4 10.20.30.123

s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 0 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20

------------------------------------------------------------------------ send 2373 bytes to udp/[10.20.30.151]:5060 at 13:40:20.244041:

------------------------------------------------------------------------ INVITE sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm Max-Forwards: 68 From: "52321;phone-context=location.systemname" <sip:52321;phone-context=location.systemname@10.20.30.123

...

;tag=K8vUtjFrQUjtg To: <sip:57331@10.20.30.151> Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea CSeq: 56461346 INVITE Contact: <sip:mod_sofia@10.20.30.123:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Privacy: none Content-Type: multipart/mixed;boundary=ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Length: 1250 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 X-FS-Support: update_display,send_info P-Asserted-Identity: "52321;phone-context=location.systemname" <sip:52321;phone-context=location.systemname@10.20.30.123>

--ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/sdp Content-Length: 262

v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122

a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv

--ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-mcdn-frag-hex Content-Length: 217

05000002 0107130081900000a200 09090f00e9a0830001008000 1315070011fa0f00a10d02010102020100cc040000754a00 1e0403008183 460e01000a0001000100010000000000 4a1c01001800010000000000000023617137990004000000000025230100 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-esn5-frag-hex Content-Length: 4

103 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/x-nt-epid-frag-hex Content-Length: 26

011201 80:17:7d:4e:b2:38 --ddb7d988-a07d-11e3-9b14-09241ec9370d Content-Type: application/sdp Content-Length: 208

v=0 o=FreeSWITCH 1393575650 1393575651 IN IP4 10.20.30.123

s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 19170 RTP/AVP 0 8 101 13

a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv

--ddb7d988-a07d-11e3-9b14-09241ec9370d--

------------------------------------------------------------------------ recv 506 bytes from udp/[10.20.30.151]:5060 at 13:40:20.257663:

------------------------------------------------------------------------ SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm From: "52321;phone-context=location.systemname" <sip:52321;phone-context=location.systemname@10.20.30.123

...

;tag=K8vUtjFrQUjtg To: "Joel White" <sip:57331@10.20.30.151>;tag=AC57CD1-9FDEC368 CSeq: 56461346 INVITE Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea Contact: <sip:57331@10.20.30.151> User-Agent: PolycomSoundPointIP-SPIP_335-UA/3.2.6.0314 Accept-Language: en Content-Length: 0

------------------------------------------------------------------------ send 409 bytes to udp/[10.20.30.151]:5060 at 13:40:20.257909:

------------------------------------------------------------------------ ACK sip:57331@10.20.30.151 SIP/2.0 Via: SIP/2.0/UDP 10.20.30.123;rport;branch=z9hG4bKSS3Kc2y6eNaFm Max-Forwards: 68 From: "52321;phone-context=location.systemname" <sip:52321;phone-context=location.systemname@10.20.30.123

...

;tag=K8vUtjFrQUjtg To: "Joel White" <sip:57331@10.20.30.151>;tag=AC57CD1-9FDEC368 Call-ID: b5166f21-1b20-1232-d8b6-d243871458ea CSeq: 56461346 ACK Content-Length: 0

------------------------------------------------------------------------ recv 1068 bytes from udp/[10.20.30.121]:5060 at 13:40:28.637828:

------------------------------------------------------------------------ BYE sip:57331;phone-context=location.systemname@10.20.30.123:5080;transport=udp SIP/2.0 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 3 BYE Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5fc-aaf3e09e-75565f26 Max-Forwards: 70 Supported: 100rel,x-nortel-sipvc,replaces User-Agent: Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.00.20 x-nt-corr-id: 0001e65a082a171c02@00c08b0bbfdc-e4e16711 Allow: INVITE,ACK,BYE,REGISTER,REFER,NOTIFY,CANCEL,PRACK,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: application/sdp Content-Length: 261

v=0 o=- 270184 1 IN IP4 10.20.30.121 s=- c=IN IP4 10.20.30.122 t=0 0 m=audio 5252 RTP/AVP 0 8 18 101 111 c=IN IP4 10.20.30.122

a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20 a=sendrecv

------------------------------------------------------------------------ send 625 bytes to udp/[10.20.30.121]:5060 at 13:40:28.648789:

------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.20.30.121:5060 ;branch=z9hG4bK-aed5fc-aaf3e09e-75565f26 From: <sip:52321;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=2ffc578-a0b6f0a-13c4-55013-aed5f0-7c8d636b-aed5f0 To: <sip:57331;phone-context=location.systemname@sip.nortel.net ;user=phone>;tag=tme5Hj11yUycm Call-ID: 4c26298-a0b6f0a-13c4-55013-aed5f0-13370bf5-aed5f0 CSeq: 3 BYE User-Agent: FreeSWITCH-mod_sofia/1.2.22+git~20140224T012236Z~aabf813ae1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0

------------------------------------------------------------------------

On Thu, Feb 27, 2014 at 3:42 PM, Brian West <brian@freeswitch.org> wrote:

...

sofia global siptrace on

That will help me a little more.

-- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com

T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)

On Feb 27, 2014, at 2:23 PM, Joel White <joelewhite@gmail.com> wrote:

...

I did add a line to the public incoming xml that uses the Say command to repeat back what $1 variable is set to. I figured it might help me in debugging

+OK log level debug [7] 2014-02-27 15:13:05.086534 [NOTICE] switch_channel.c:1050 New Channel sofia/external/23673 [910ede7a-9feb-11e3-9a55-09241ec9370d] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_NEW 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:7868 sofia/external/23673 receiving invite from 10.111.11.10:5060 version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [received][100] 2014-02-27 15:13:05.086534 [DEBUG] sofia.c:5824 Remote SDP: v=0 o=- 269323 1 IN IP4 10.111.11.10 s=- c=IN IP4 10.111.11.17 t=0 0 m=audio 5218 RTP/AVP 0 8 18 101 111 c=IN IP4 10.111.11.17 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:111 X-nt-inforeq/8000 a=ptime:20

2014-02-27 15:13:05.086534 [DEBUG] sofia.c:6071 (sofia/external/23673) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:434 (sofia/external/23673) State NEW 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_INIT 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:87 sofia/external/23673 SOFIA INIT 2014-02-27 15:13:05.086534 [DEBUG] mod_sofia.c:127 (sofia/external/23673) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:455 (sofia/external/23673) State INIT going to sleep 2014-02-27 15:13:05.086534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:05.086534 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change DOWN -> RINGING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:05.106494 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365;phone-context=location.systemname in context public Dialplan: sofia/external/23673 parsing [public->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [public->outside_call] continue=true Dialplan: sofia/external/23673 Absolute Condition [outside_call] Dialplan: sofia/external/23673 Action set(outside_call=true) Dialplan: sofia/external/23673 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/23673 parsing [public->call_debug] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 parsing [public->public_extensions] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_extensions] destination_number(28365;phone-context=location.systemname) =~ /^([456][0-9][0-9][0-9]/d?)$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_mgw00_inbound] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [public_did_mgw00_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5})$/ break=on-false Dialplan: sofia/external/23673 parsing [public->public_did_nortel_inbound] continue=false Dialplan: sofia/external/23673 Regex (PASS) [public_did_nortel_inbound] destination_number(28365;phone-context=location.systemname) =~ /^(\d{5});(.*)$/ break=on-false Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action say(en number iterated 28365) Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action set(domain_name=10.20.30.123) Dialplan: sofia/external/23673 Action transfer(28365 XML default) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:05.106494 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(outside_call=true) 2014-02-27 15:13:05.106494 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [outside_call]=[true] EXECUTE sofia/external/23673 export(RFC2822_DATE=Thu, 27 Feb 2014 15:13:05 -0500) 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] EXECUTE sofia/external/23673 answer() 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3190 Set Codec sofia/external/23673 PCMU/8000 20 ms 160 samples 64000 bits 2014-02-27 15:13:05.106494 [DEBUG] switch_core_codec.c:111 sofia/external/23673 Original read codec set to PCMU:0 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:5451 Set 2833 dtmf send/recv payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3449 AUDIO RTP [sofia/external/23673] 10.20.30.123 port 20854 -> 10.111.11.17 port 5218 codec: 0 ms: 20 2014-02-27 15:13:05.106494 [DEBUG] switch_rtp.c:2033 Starting timer [soft] 160 bytes per 20ms 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf send payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3722 Set 2833 dtmf receive payload to 101 2014-02-27 15:13:05.106494 [DEBUG] sofia_glue.c:3749 sofia/external/23673 Set rtp dtmf delay to 40 2014-02-27 15:13:05.106494 [NOTICE] sofia_glue.c:4360 Pre-Answer sofia/external/23673! 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3367 (sofia/external/23673) Callstate Change RINGING -> EARLY 2014-02-27 15:13:05.106494 [DEBUG] mod_sofia.c:866 Local SDP sofia/external/23673: v=0 o=FreeSWITCH 1393511131 1393511132 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 20854 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

2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [completed][200] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [NOTICE] mod_dptools.c:1225 Channel [sofia/external/23673] has been answered 2014-02-27 15:13:05.106494 [DEBUG] switch_channel.c:3646 (sofia/external/23673) Callstate Change EARLY -> ACTIVE EXECUTE sofia/external/23673 say(en number iterated 28365) 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.106494 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:05.126485 [DEBUG] sofia.c:5811 Channel sofia/external/23673 entering state [ready][200] 2014-02-27 15:13:05.126485 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:05.226537 [DEBUG] switch_rtp.c:3749 Correct ip/port confirmed. 2014-02-27 15:13:07.666516 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/2.wav!digits/8.wav!digits/3.wav!digits/6.wav!digits/5.wav EXECUTE sofia/external/23673 sleep(1000) EXECUTE sofia/external/23673 set(domain_name=10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [domain_name]=[10.20.30.123] EXECUTE sofia/external/23673 transfer(28365 XML default) 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr.c:1832 (sofia/external/23673) State Change CS_EXECUTE -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [NOTICE] switch_ivr.c:1839 Transfer sofia/external/23673 to XML[28365@default] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2163 (sofia/external/23673) Callstate Change ACTIVE -> RINGING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/external/23673 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:117 sofia/external/23673 Standard ROUTING 2014-02-27 15:13:08.666549 [INFO] mod_dialplan_xml.c:558 Processing 23673;phone-context=location.systemname <23673;phone-context=location.systemname>->28365 in context default Dialplan: sofia/external/23673 parsing [default->unloop] continue=false Dialplan: sofia/external/23673 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/23673 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/23673 parsing [default->tod_example] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->tod_brevard] continue=true Dialplan: sofia/external/23673 Date/Time Match (PASS) [tod_brevard] break=on-false Dialplan: sofia/external/23673 Action set(open=true) Dialplan: sofia/external/23673 parsing [default->holiday_example] continue=true Dialplan: sofia/external/23673 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/23673 parsing [default->global-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [global-intercept] destination_number(28365) =~ /^886$/ break=on-false Dialplan: sofia/external/23673 parsing [default->group-intercept] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [group-intercept] destination_number(28365) =~ /^\*8$/ break=on-false Dialplan: sofia/external/23673 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [intercept-ext] destination_number(28365) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->redial] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [redial] destination_number(28365) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->global] continue=true Dialplan: sofia/external/23673 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/external/23673 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/23673 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [eavesdrop] destination_number(28365) =~ /^779$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call_return] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call_return] destination_number(28365) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/23673 parsing [default->del-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [del-group] destination_number(28365) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->add-group] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [add-group] destination_number(28365) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-simo] destination_number(28365) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->call-group-order] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [call-group-order] destination_number(28365) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/23673 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [extension-intercom] destination_number(28365) =~ /^8([456][0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_4_digit] continue=false Dialplan: sofia/external/23673 Regex (FAIL) [Local_Extension_4_digit] destination_number(28365) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/23673 parsing [default->Local_Extension_5_digit] continue=false Dialplan: sofia/external/23673 Regex (PASS) [Local_Extension_5_digit] destination_number(28365) =~ /^(5[0-9][0-9][0-9][0-9])$/ break=on-false Dialplan: sofia/external/23673 Action export(dialed_extension=28365) Dialplan: sofia/external/23673 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/external/23673 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/external/23673 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/external/23673 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/external/23673 Action set(ringback=${us-ring}) Dialplan: sofia/external/23673 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/external/23673 Action set(call_timeout=30) Dialplan: sofia/external/23673 Action set(hangup_after_bridge=true) Dialplan: sofia/external/23673 Action set(continue_on_fail=true) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/23673 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/external/23673 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/23673 Action bridge(user/${dialed_extension}@ ${domain_name}) Dialplan: sofia/external/23673 Action answer() Dialplan: sofia/external/23673 Action sleep(1000) Dialplan: sofia/external/23673 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:167 (sofia/external/23673) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/external/23673) State ROUTING going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:2165 (sofia/external/23673) Callstate Change RINGING -> ACTIVE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:243 sofia/external/23673 SOFIA EXECUTE 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:209 sofia/external/23673 Standard EXECUTE EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 set(open=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [open]=[true] EXECUTE sofia/external/23673 export(dialed_extension=28365) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1242 EXPORT (export_vars) [dialed_extension]=[28365] EXECUTE sofia/external/23673 bind_meta_app(1 b s execute_extension::dx XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/external/23673 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/23673;phone-context=location.systemname.2014-02-27-15-13-08.wav EXECUTE sofia/external/23673 bind_meta_app(3 b s execute_extension::cf XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/external/23673 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2014-02-27 15:13:08.666549 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/external/23673 set(ringback=%(2000,4000,440,480)) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/23673 set(transfer_ringback=local_stream://moh) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/external/23673 set(call_timeout=30) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [call_timeout]=[30] EXECUTE sofia/external/23673 set(hangup_after_bridge=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [hangup_after_bridge]=[true] EXECUTE sofia/external/23673 set(continue_on_fail=true) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [continue_on_fail]=[true] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-call_return/ 28365/23673;phone-context=location.systemname) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/28365/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 set(called_party_callgroup=techsupport) 2014-02-27 15:13:08.666549 [DEBUG] mod_dptools.c:1402 sofia/external/23673 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial_ext/global/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 hash(insert/10.20.30.123-last_dial/techsupport/910ede7a-9feb-11e3-9a55-09241ec9370d) EXECUTE sofia/external/23673 bridge(user/28365@10.20.30.123) 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [sip_invite_domain]=[10.20.30.123] 2014-02-27 15:13:08.666549 [DEBUG] switch_event.c:1661 Parsing variable [presence_id]=[28365@10.20.30.123] 2014-02-27 15:13:08.666549 [NOTICE] switch_channel.c:1050 New Channel sofia/internal/sip:28365@10.20.30.121[93309eb4-9feb-11e3-9a76-09241ec9370d] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5230 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5300 [zrtp_passthru] Setting a-leg inherit_codec=true 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:5303 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMU@8000h@20i@64000b,PCMA@8000h @20i@64000b' 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_INIT 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:87 sofia/internal/ sip:28365@10.20.30.121 SOFIA INIT 2014-02-27 15:13:08.666549 [DEBUG] sofia_glue.c:2744 sofia/internal/ sip:28365@10.20.30.121 sending invite version: 1.2.22 git aabf813 2014-02-24 01:22:36Z 64bit Local SDP: v=0 o=FreeSWITCH 1393508912 1393508913 IN IP4 10.20.30.123 s=FreeSWITCH c=IN IP4 10.20.30.123 t=0 0 m=audio 23076 RTP/AVP 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv

2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:127 (sofia/internal/ sip:28365@10.20.30.121) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:28365@10.20.30.121) State INIT going to sleep 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_ROUTING 2014-02-27 15:13:08.666549 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [calling][0] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING 2014-02-27 15:13:08.666549 [DEBUG] mod_sofia.c:150 sofia/internal/ sip:28365@10.20.30.121 SOFIA ROUTING 2014-02-27 15:13:08.666549 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:28365@10.20.30.121) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:08.666549 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.666549 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:28365@10.20.30.121) State ROUTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:28365@10.20.30.121) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] sofia.c:5811 Channel sofia/internal/ sip:28365@10.20.30.121 entering state [terminated][415] 2014-02-27 15:13:08.686500 [NOTICE] sofia.c:6655 Hangup sofia/internal/ sip:28365@10.20.30.121 [CS_CONSUME_MEDIA] [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.686500 [DEBUG] switch_channel.c:3186 Send signal sofia/internal/sip:28365@10.20.30.121 [KILL] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/sip:28365@10.20.30.121) Callstate Change DOWN -> HANGUP 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP 2014-02-27 15:13:08.686500 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:28365@10.20.30.121 hanging up, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:28365@10.20.30.121 Standard HANGUP, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:680 (sofia/internal/sip:28365@10.20.30.121) State HANGUP going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/sip:28365@10.20.30.121) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:28365@10.20.30.121 Standard REPORTING, cause: SERVICE_NOT_IMPLEMENTED 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:28365@10.20.30.121) State REPORTING going to sleep 2014-02-27 15:13:08.686500 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/sip:28365@10.20.30.121) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:28365@10.20.30.121 [BREAK] 2014-02-27 15:13:08.686500 [DEBUG] switch_core_session.c:1559 Session 2 (sofia/internal/sip:28365@10.20.30.121) Locked, Waiting on external entities 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:08.706527 [NOTICE] switch_ivr_originate.c:2670 Cannot create outgoing channel of type [user] cause: [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [DEBUG] switch_ivr_originate.c:3657 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED] 2014-02-27 15:13:08.706527 [INFO] mod_dptools.c:3201 Originate Failed. Cause: SERVICE_NOT_IMPLEMENTED EXECUTE sofia/external/23673 answer() EXECUTE sofia/external/23673 sleep(1000) 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1577 Session 2 (sofia/internal/sip:28365@10.20.30.121) Ended 2014-02-27 15:13:08.706527 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/sip:28365@10.20.30.121 [CS_DESTROY] 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/sip:28365@10.20.30.121) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:28365@10.20.30.121) Running State Change CS_DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY 2014-02-27 15:13:08.706527 [DEBUG] mod_sofia.c:399 sofia/internal/ sip:28365@10.20.30.121 SOFIA DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:28365@10.20.30.121 Standard DESTROY 2014-02-27 15:13:08.706527 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:28365@10.20.30.121) State DESTROY going to sleep EXECUTE sofia/external/23673 bridge(loopback/app=voicemail:default 10.20.30.123 28365) 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1763 (sofia/external/23673) Callstate Change ACTIVE -> RING_WAIT 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 27 Feb 2014 15:13:05 -0500] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:1196 sofia/external/23673 EXPORTING[export_vars] [dialed_extension]=[28365] to event 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/app=voicemail:default 10.20.30.123 28365-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 10.20.30.123 28365-a setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1048 Rename Channel loopback/app=voicemail:default 10.20.30.123 28365-a->loopback/voicemail-a [93cd50f6-9feb-11e3-9a7f-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:1158 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT 2014-02-27 15:13:09.706545 [NOTICE] switch_channel.c:1050 New Channel loopback/voicemail-b [93cd7874-9feb-11e3-9a83-09241ec9370d] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMU/8000/20 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:272 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-a CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:648 CHANNEL CONSUME_MEDIA 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_INIT 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:357 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_ROUTING 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:2163 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:389 loopback/voicemail-b CHANNEL ROUTING 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:408 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING going to sleep 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:431 loopback/voicemail-b CHANNEL EXECUTE 2014-02-27 15:13:09.706545 [DEBUG] switch_core_state_machine.c:209 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2014-02-27 15:13:09.706545 [NOTICE] mod_loopback.c:945 Pre-Answer loopback/voicemail-a! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3363 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2014-02-27 15:13:09.706545 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:09.706545 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:09.706545 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2014-02-27 15:13:09.706545 [DEBUG] switch_channel.c:3367 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 10.20.30.123 28365) 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_originate.c:3513 Originate Resulted in Success: [loopback/voicemail-a] 2014-02-27 15:13:09.726502 [DEBUG] switch_channel.c:1967 (sofia/external/23673) Callstate Change RING_WAIT -> ACTIVE 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:871 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] switch_ivr_bridge.c:1429 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA 2014-02-27 15:13:09.726502 [DEBUG] mod_loopback.c:610 CHANNEL LOOPBACK 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2014-02-27 15:13:09.826538 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:11.206539 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:251 Handle say:[28365] (en:en) 2014-02-27 15:13:11.306570 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:13.866518 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/5.wav!digits/7.wav!digits/3.wav!digits/3.wav!digits/1.wav 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2014-02-27 15:13:13.966519 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:14.946549 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2014-02-27 15:13:15.046549 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-02-27 15:13:15.646531 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] sofia.c:737 Hangup sofia/external/23673 [CS_EXECUTE] [NORMAL_CLEARING] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal sofia/external/23673 [KILL] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/external/23673] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:557 sofia/external/23673 ending bridge by request from write function 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [loopback/voicemail-a] 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:661 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [NOTICE] switch_ivr_bridge.c:722 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-a [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:535 loopback/voicemail-a CHANNEL HANGUP 2014-02-27 15:13:15.666534 [NOTICE] mod_loopback.c:551 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-02-27 15:13:15.666534 [DEBUG] switch_channel.c:3186 Send signal loopback/voicemail-b [KILL] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-a) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-a) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 3 (loopback/voicemail-a) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [DEBUG] switch_ivr_bridge.c:1530 sofia/external/23673 skip receive message [UNBRIDGE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:2810 sofia/external/23673 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:478 (sofia/external/23673) State EXECUTE going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:678 (sofia/external/23673) Callstate Change ACTIVE -> HANGUP 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:500 sofia/external/23673 Overriding SIP cause 480 with 415 from the other leg 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:506 Channel sofia/external/23673 hanging up, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:48 sofia/external/23673 Standard HANGUP, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:680 (sofia/external/23673) State HANGUP going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:447 (sofia/external/23673) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:415 (sofia/external/23673) Running State Change CS_REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:92 sofia/external/23673 Standard REPORTING, cause: NORMAL_CLEARING 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:764 (sofia/external/23673) State REPORTING going to sleep 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:441 (sofia/external/23673) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/23673 [BREAK] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_session.c:1559 Session 1 (sofia/external/23673) Locked, Waiting on external entities 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1577 Session 1 (sofia/external/23673) Ended 2014-02-27 15:13:15.666534 [NOTICE] switch_core_session.c:1581 Close Channel sofia/external/23673 [CS_DESTROY] 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:566 (sofia/external/23673) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:569 (sofia/external/23673) Running State Change CS_DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY 2014-02-27 15:13:15.666534 [DEBUG] mod_sofia.c:399 sofia/external/23673 SOFIA DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:99 sofia/external/23673 Standard DESTROY 2014-02-27 15:13:15.666534 [DEBUG] switch_core_state_machine.c:579 (sofia/external/23673) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:2810 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:678 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:535 loopback/voicemail-b CHANNEL HANGUP 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:680 (loopback/voicemail-b) State HANGUP going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:764 (loopback/voicemail-b) State REPORTING going to sleep 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-02-27 15:13:15.686490 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-02-27 15:13:15.686490 [DEBUG] switch_core_session.c:1559 Session 4 (loopback/voicemail-b) Locked, Waiting on external entities 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 4 (loopback/voicemail-b) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-b [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-b) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-b Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY going to sleep 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1577 Session 3 (loopback/voicemail-a) Ended 2014-02-27 15:13:15.686490 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-a [CS_DESTROY] 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-a) Running State Change CS_DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-a Standard DESTROY 2014-02-27 15:13:15.686490 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY going to sleep

_________________________________________________________________________

...

Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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

_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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