<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"><head><meta http-equiv=Content-Type content="text/html; charset=us-ascii"><meta name=Generator content="Microsoft Word 14 (filtered medium)"><style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]--></head><body lang=EN-US link=blue vlink=purple><div class=WordSection1><p class=MsoNormal>I can’t seem to find any info on the problem I am having by searching the archives, so I apologize if this has been answered in the past (found several about MANDATORY_IE_MISSING but they were different situations).<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>I am trying to setup FreeSWITCH using a FreeTDM + libpri + DAHDI + foneBridge2 stack. Outgoing calls work great, but I am running into the ‘MANDATORY_IE_MISSING’ problem with incoming calls. I am running the latest git version as of this morning, and completely default configuration with the exception of FreeTDM/DAHDI configuration and a modification of the default inbound_did dialplan to pass my DID 5530 to the default extension 1001.<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Below is what I get in the log, I highlighted in <span style='color:#C00000'>RED</span> as soon as the call appears to start failing -<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [NOTICE] ftmod_libpri.c:1363 -- Ring on channel 1:1 (from ********** to 5530)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:1394 RING event with complete indicator (or overlap receive disabled)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:1395 [s1c1][1:1] Changed state from DOWN to RING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for RING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [RING]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from DOWN to RING in 0ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:2416 got clear channel sig [START]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] ftdm_io.c:3131 [s1c1][1:1] Enabled software DTMF detector<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:407 Set codec PCMU 20ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:1740 Connect inbound channel FreeTDM/1:1/5530<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [NOTICE] switch_channel.c:924 New Channel FreeTDM/1:1/5530 [f11ea7a0-3a5d-11e1-a157-018f03d45a74]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:1846 (FreeTDM/1:1/5530) State Change CS_NEW -> CS_INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/5530) State INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:435 (FreeTDM/1:1/5530) State Change CS_INIT -> CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/5530) State INIT going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_channel.c:1884 (FreeTDM/1:1/5530) Callstate Change DOWN -> RINGING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/5530 CHANNEL ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state RING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Changed state from RING to PROCEED<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROCEED<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROCEED]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from RING to PROCEED in 55ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/5530 Standard ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] mod_dialplan_xml.c:481 Processing ********** <**********>->5530 in context public<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [public->unloop] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [public->outside_call] continue=true<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Absolute Condition [outside_call]<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(outside_call=true) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [public->call_debug] continue=true<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [public->public_extensions] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [public_extensions] destination_number(5530) =~ /^(10[01][0-9])$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [public->public_did] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (PASS) [public_did] destination_number(5530) =~ /^(5530)$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(domain_name=xx.xx.xx.xxx) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action transfer(1001 XML default) <o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/5530) State Change CS_ROUTING -> CS_EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/5530 CHANNEL EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/5530 Standard EXECUTE<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(outside_call=true)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [outside_call]=[true]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(RFC2822_DATE=Sun, 08 Jan 2012 18:04:55 -0700)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [RFC2822_DATE]=[Sun, 08 Jan 2012 18:04:55 -0700]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(domain_name=xx.xx.xx.xxx)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [domain_name]=[xx.xx.xx.xxx]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 transfer(1001 XML default)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_ivr.c:1711 (FreeTDM/1:1/5530) State Change CS_EXECUTE -> CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [NOTICE] switch_ivr.c:1717 Transfer FreeTDM/1:1/5530 to XML[1001@default]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/5530 CHANNEL ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state PROCEED<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/5530 Standard ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] mod_dialplan_xml.c:481 Processing ********** <**********>->1001 in context default<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->unloop] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->tod_example] continue=true<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Date/TimeMatch (FAIL) [tod_example] break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->holiday_example] continue=true<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Date/TimeMatch (FAIL) [holiday_example] break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->global-intercept] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->group-intercept] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->intercept-ext] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->redial] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->global] continue=true<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Absolute Condition [global]<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/global/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->snom-demo-2] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->snom-demo-1] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->eavesdrop] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->eavesdrop] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->call_return] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->del-group] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->add-group] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->call-group-simo] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->call-group-order] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->extension-intercom] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 parsing [default->Local_Extension] continue=false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false<o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action export(dialed_extension=1001) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(1 b s execute_extension::dx XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(3 b s execute_extension::cf XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(ringback=${us-ring}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(transfer_ringback=local_stream://moh) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(call_timeout=30) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(hangup_after_bridge=true) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(continue_on_fail=true) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bridge(user/${dialed_extension}@${domain_name}) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action answer() <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action sleep(1000) <o:p></o:p></p><p class=MsoNormal>Dialplan: FreeTDM/1:1/5530 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) <o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/5530) State Change CS_ROUTING -> CS_EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/5530 CHANNEL EXECUTE<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/5530 Standard EXECUTE<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-spymap/**********/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/**********/1001)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/global/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(RFC2822_DATE=Sun, 08 Jan 2012 18:04:55 -0700)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [RFC2822_DATE]=[Sun, 08 Jan 2012 18:04:55 -0700]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 export(dialed_extension=1001)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1091 EXPORT (export_vars) [dialed_extension]=[1001]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 bind_meta_app(1 b s execute_extension::dx XML features)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *1 execute_extension::dx XML features<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/**********.2012-01-08-18-04-55.wav)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/**********.2012-01-08-18-04-55.wav<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 bind_meta_app(3 b s execute_extension::cf XML features)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *3 execute_extension::cf XML features<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 bind_meta_app(4 b s execute_extension::att_xfer XML features)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *4 execute_extension::att_xfer XML features<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(ringback=%(2000,4000,440,480))<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [ringback]=[%(2000,4000,440,480)]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(transfer_ringback=local_stream://moh)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [transfer_ringback]=[local_stream://moh]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(call_timeout=30)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [call_timeout]=[30]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(hangup_after_bridge=true)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [hangup_after_bridge]=[true]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(continue_on_fail=true)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [continue_on_fail]=[true]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-call_return/1001/**********)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/1001/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 set(called_party_callgroup=techsupport)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [called_party_callgroup]=[techsupport]<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/techsupport/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/global/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/techsupport/f11ea7a0-3a5d-11e1-a157-018f03d45a74)<o:p></o:p></p><p class=MsoNormal>EXECUTE FreeTDM/1:1/5530 bridge(user/1001@xx.xx.xx.xxx)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[xx.xx.xx.xxx]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[1001@xx.xx.xx.xxx]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [NOTICE] switch_channel.c:924 New Channel sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [f1292a54-3a5d-11e1-a15e-018f03d45a74]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:4674 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State Change CS_NEW -> CS_INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:85 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA INIT<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State Change CS_INIT -> CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State INIT going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1884 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Callstate Change DOWN -> RINGING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:148 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA ROUTING<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State Change CS_ROUTING -> CS_CONSUME_MEDIA<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State ROUTING going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_CONSUME_MEDIA<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State CONSUME_MEDIA<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State CONSUME_MEDIA going to sleep<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.006902 [DEBUG] sofia.c:5482 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:52564 entering state [calling][0]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1668 Got a FACILITY event on span 1:1<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1697 FACILITY subcommand 2 is not implemented, ignoring<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1700 FACILITY subcommand 2 handler returned -1<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1703 Caught Event on span 1 11 (FACILITY)<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [DEBUG] sofia.c:5482 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:52564 entering state [proceeding][180]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [NOTICE] sofia.c:5574 Ring-Ready sofia/internal/sip:1001@xx.xx.xx.xxx:52564!<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Indicating PROGRESS_MEDIA in state PROCEED<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.126907 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROCEED to PROGRESS<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.146908 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.146908 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.146908 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROCEED to PROGRESS in 22ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.146908 [ERR] ftmod_libpri.c:132 XXX Progress message requested but no information is provided<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.146908 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROGRESS to PROGRESS_MEDIA<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS_MEDIA<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS_MEDIA]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROGRESS to PROGRESS_MEDIA in 55ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [INFO] ftmod_zt.c:656 Setting echo cancel to 64 taps for 1:1<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [WARNING] ftmod_zt.c:661 Echo cancel not available for 1:1<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [NOTICE] switch_ivr_originate.c:1115 Pre-Answer FreeTDM/1:1/5530!<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] switch_channel.c:2930 (FreeTDM/1:1/5530) Callstate Change RINGING -> EARLY<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] switch_ivr_originate.c:1164 Raw Codec Activation Success L16@8000hz 1 channel 20ms<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] switch_core_codec.c:116 FreeTDM/1:1/5530 Push codec L16:70<o:p></o:p></p><p class=MsoNormal>2012-01-08 18:04:55.206902 [DEBUG] switch_ivr_originate.c:1227 Play Ringback Tone [%(2000,4000,440,480)]<o:p></o:p></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:1065 -- Hangup REQ on channel 1:1<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:1078 [s1c1][1:1] Changed state from PROGRESS_MEDIA to TERMINATING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for TERMINATING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [TERMINATING]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROGRESS_MEDIA to TERMINATING in 0ms<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] ftdm_io.c:5565 [s1c1][1:1] Scheduling safety hangup timer<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] mod_freetdm.c:2416 got clear channel sig [STOP]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] switch_channel.c:2846 (FreeTDM/1:1/5530) Callstate Change EARLY -> HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [NOTICE] mod_freetdm.c:2441 Hangup FreeTDM/1:1/5530 [CS_EXECUTE] [MANDATORY_IE_MISSING]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] switch_channel.c:2869 Send signal FreeTDM/1:1/5530 [KILL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.226909 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_codec.c:141 FreeTDM/1:1/5530 Restore previous codec PCMU:0.<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_channel.c:2846 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Callstate Change RINGING -> HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_ivr_originate.c:3182 Hangup sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_channel.c:2869 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [KILL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_ivr_originate.c:3358 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_ivr_originate.c:2459 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [INFO] mod_dptools.c:2900 Originate Failed. Cause: ORIGINATOR_CANCEL<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:2285 FreeTDM/1:1/5530 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:52564 hanging up, cause: ORIGINATOR_CANCEL<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:530 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP ENTER<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:605 [s1c1][1:1] Changed state from TERMINATING to HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/internal/sip:1001@xx.xx.xx.xxx:52564<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 Standard HANGUP, cause: ORIGINATOR_CANCEL<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State HANGUP going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State Change CS_HANGUP -> CS_REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 Standard REPORTING, cause: ORIGINATOR_CANCEL<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State REPORTING going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State Change CS_REPORTING -> CS_DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1380 Session 2 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Locked, Waiting on external entities<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1398 Session 2 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Ended<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [CS_DESTROY]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Callstate Change HANGUP -> DOWN<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) Running State Change CS_DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:374 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 Standard DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:1001@xx.xx.xx.xxx:52564) State DESTROY going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from TERMINATING to HANGUP in 15ms<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:929 [s1c1][1:1] Changed state from HANGUP to HANGUP_COMPLETE<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP_COMPLETE<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP_COMPLETE]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from HANGUP to HANGUP_COMPLETE in 0ms<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:939 [s1c1][1:1] Changed state from HANGUP_COMPLETE to DOWN<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for DOWN<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [DOWN]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from HANGUP_COMPLETE to DOWN in 0ms<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2930 [s1c1][1:1] DTMF debug is already disabled<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2962 [s1c1][1:1] No need to disable input dump<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2993 [s1c1][1:1] No need to disable output dump<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:2416 got clear channel sig [RELEASED]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:6185 Cleared call with id 1<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2735 [s1c1][1:1] channel done<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:704 -- Closed channel 1:1<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:624 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP EXIT<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:47 FreeTDM/1:1/5530 Standard HANGUP, cause: MANDATORY_IE_MISSING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:393 (FreeTDM/1:1/5530) State Change CS_HANGUP -> CS_REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:79 FreeTDM/1:1/5530 Standard REPORTING, cause: MANDATORY_IE_MISSING<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING going to sleep<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:387 (FreeTDM/1:1/5530) State Change CS_REPORTING -> CS_DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1380 Session 1 (FreeTDM/1:1/5530) Locked, Waiting on external entities<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1398 Session 1 (FreeTDM/1:1/5530) Ended<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1400 Close Channel FreeTDM/1:1/5530 [CS_DESTROY]<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:491 (FreeTDM/1:1/5530) Callstate Change HANGUP -> DOWN<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:494 (FreeTDM/1:1/5530) Running State Change CS_DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:86 FreeTDM/1:1/5530 Standard DESTROY<o:p></o:p></span></p><p class=MsoNormal><span style='color:#C00000'>2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY going to sleep<o:p></o:p></span></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Full log (including loading FreeSWITCH) at <a href="http://pastebin.com/vQUHu0pR">http://pastebin.com/vQUHu0pR</a><o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>freeswitch/conf/freetdm.conf – <o:p></o:p></p><p class=MsoNormal>[span zt PRI]<o:p></o:p></p><p class=MsoNormal>trunk_type => T1<o:p></o:p></p><p class=MsoNormal>b-channel=1-23<o:p></o:p></p><p class=MsoNormal>d-channel=24<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>freeswitch/conf/autoload_confg/freetdm.conf.xml –<o:p></o:p></p><p class=MsoNormal><configuration name="freetdm.conf" description="FreeTDM Configuration"><o:p></o:p></p><p class=MsoNormal> <settings><o:p></o:p></p><p class=MsoNormal> <param name="debug" value="1"/><o:p></o:p></p><p class=MsoNormal> </settings><o:p></o:p></p><p class=MsoNormal> <libpri_spans><o:p></o:p></p><p class=MsoNormal> <span name="PRI"><o:p></o:p></p><p class=MsoNormal> <param name="node" value="cpe"/><o:p></o:p></p><p class=MsoNormal> <param name="switch" value="ni2"/><o:p></o:p></p><p class=MsoNormal> <param name="dialplan" value="XML"/><o:p></o:p></p><p class=MsoNormal> <param name="context" value="public"/><o:p></o:p></p><p class=MsoNormal> <param name="l1" value="ulaw"/><o:p></o:p></p><p class=MsoNormal> </span><o:p></o:p></p><p class=MsoNormal> </libpri_spans><o:p></o:p></p><p class=MsoNormal></configuration><o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>/etc/dahdi/system.conf –<o:p></o:p></p><p class=MsoNormal>loadzone = us<o:p></o:p></p><p class=MsoNormal>defaultzone=us<o:p></o:p></p><p class=MsoNormal>dynamic=ethmf,eth0/00:50:c2:65:d7:59/0,24,1<o:p></o:p></p><p class=MsoNormal>bchan=1-23<o:p></o:p></p><p class=MsoNormal>dchan=24<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>I am guessing it is a configuration issue, though this same config is currently working in production with FreeSWITCH 1.0.6 + OpenZAP + Libpri + DAHDI + foneBridge2.<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Any help is greatly appreciated.<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>-Adam<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal><o:p> </o:p></p></div></body></html>