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). 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. Below is what I get in the log, I highlighted in RED as soon as the call appears to start failing - 2012-01-08 18:04:54.946902 [NOTICE] ftmod_libpri.c:1363 -- Ring on channel 1:1 (from ********** to 5530) 2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:1394 RING event with complete indicator (or overlap receive disabled) 2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:1395 [s1c1][1:1] Changed state from DOWN to RING 2012-01-08 18:04:54.946902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for RING 2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [RING] 2012-01-08 18:04:54.946902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from DOWN to RING in 0ms 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:2416 got clear channel sig [START] 2012-01-08 18:04:54.946902 [DEBUG] ftdm_io.c:3131 [s1c1][1:1] Enabled software DTMF detector 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:407 Set codec PCMU 20ms 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:1740 Connect inbound channel FreeTDM/1:1/5530 2012-01-08 18:04:54.946902 [NOTICE] switch_channel.c:924 New Channel FreeTDM/1:1/5530 [f11ea7a0-3a5d-11e1-a157-018f03d45a74] 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:1846 (FreeTDM/1:1/5530) State Change CS_NEW -> CS_INIT 2012-01-08 18:04:54.946902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_INIT 2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/5530) State INIT 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:435 (FreeTDM/1:1/5530) State Change CS_INIT -> CS_ROUTING 2012-01-08 18:04:54.946902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/5530) State INIT going to sleep 2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_ROUTING 2012-01-08 18:04:54.946902 [DEBUG] switch_channel.c:1884 (FreeTDM/1:1/5530) Callstate Change DOWN -> RINGING 2012-01-08 18:04:54.946902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/5530 CHANNEL ROUTING 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state RING 2012-01-08 18:04:54.946902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Changed state from RING to PROCEED 2012-01-08 18:04:55.006902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROCEED 2012-01-08 18:04:55.006902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROCEED] 2012-01-08 18:04:55.006902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from RING to PROCEED in 55ms 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/5530 Standard ROUTING 2012-01-08 18:04:55.006902 [INFO] mod_dialplan_xml.c:481 Processing ********** <**********>->5530 in context public Dialplan: FreeTDM/1:1/5530 parsing [public->unloop] continue=false Dialplan: FreeTDM/1:1/5530 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [public->outside_call] continue=true Dialplan: FreeTDM/1:1/5530 Absolute Condition [outside_call] Dialplan: FreeTDM/1:1/5530 Action set(outside_call=true) Dialplan: FreeTDM/1:1/5530 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: FreeTDM/1:1/5530 parsing [public->call_debug] continue=true Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: FreeTDM/1:1/5530 parsing [public->public_extensions] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [public_extensions] destination_number(5530) =~ /^(10[01][0-9])$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [public->public_did] continue=false Dialplan: FreeTDM/1:1/5530 Regex (PASS) [public_did] destination_number(5530) =~ /^(5530)$/ break=on-false Dialplan: FreeTDM/1:1/5530 Action set(domain_name=xx.xx.xx.xxx) Dialplan: FreeTDM/1:1/5530 Action transfer(1001 XML default) 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/5530) State Change CS_ROUTING -> CS_EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING going to sleep 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/5530 CHANNEL EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/5530 Standard EXECUTE EXECUTE FreeTDM/1:1/5530 set(outside_call=true) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [outside_call]=[true] EXECUTE FreeTDM/1:1/5530 set(RFC2822_DATE=Sun, 08 Jan 2012 18:04:55 -0700) 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] EXECUTE FreeTDM/1:1/5530 set(domain_name=xx.xx.xx.xxx) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [domain_name]=[xx.xx.xx.xxx] EXECUTE FreeTDM/1:1/5530 transfer(1001 XML default) 2012-01-08 18:04:55.006902 [DEBUG] switch_ivr.c:1711 (FreeTDM/1:1/5530) State Change CS_EXECUTE -> CS_ROUTING 2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.006902 [NOTICE] switch_ivr.c:1717 Transfer FreeTDM/1:1/5530 to XML[1001@default] 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE going to sleep 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_ROUTING 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING 2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/5530 CHANNEL ROUTING 2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state PROCEED 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/5530 Standard ROUTING 2012-01-08 18:04:55.006902 [INFO] mod_dialplan_xml.c:481 Processing ********** <**********>->1001 in context default Dialplan: FreeTDM/1:1/5530 parsing [default->unloop] continue=false Dialplan: FreeTDM/1:1/5530 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->tod_example] continue=true Dialplan: FreeTDM/1:1/5530 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->holiday_example] continue=true Dialplan: FreeTDM/1:1/5530 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->global-intercept] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->group-intercept] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->intercept-ext] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->redial] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->global] continue=true Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never 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 Dialplan: FreeTDM/1:1/5530 Absolute Condition [global] Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_numbe r}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: FreeTDM/1:1/5530 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: FreeTDM/1:1/5530 parsing [default->snom-demo-2] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->snom-demo-1] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->eavesdrop] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->eavesdrop] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->call_return] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->del-group] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->add-group] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->call-group-simo] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->call-group-order] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->extension-intercom] continue=false Dialplan: FreeTDM/1:1/5530 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: FreeTDM/1:1/5530 parsing [default->Local_Extension] continue=false Dialplan: FreeTDM/1:1/5530 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: FreeTDM/1:1/5530 Action export(dialed_extension=1001) Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strft ime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: FreeTDM/1:1/5530 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: FreeTDM/1:1/5530 Action set(ringback=${us-ring}) Dialplan: FreeTDM/1:1/5530 Action set(transfer_ringback=local_stream://moh) Dialplan: FreeTDM/1:1/5530 Action set(call_timeout=30) Dialplan: FreeTDM/1:1/5530 Action set(hangup_after_bridge=true) Dialplan: FreeTDM/1:1/5530 Action set(continue_on_fail=true) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_numbe r}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: FreeTDM/1:1/5530 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: FreeTDM/1:1/5530 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: FreeTDM/1:1/5530 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: FreeTDM/1:1/5530 Action answer() Dialplan: FreeTDM/1:1/5530 Action sleep(1000) Dialplan: FreeTDM/1:1/5530 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/5530) State Change CS_ROUTING -> CS_EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING going to sleep 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/5530 CHANNEL EXECUTE 2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/5530 Standard EXECUTE EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-spymap/**********/f11ea7a0-3a5d-11e1-a157-018f03d45 a74) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/**********/1001) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/global/f11ea7a0-3a5d-11e1-a157-018f03d45a 74) EXECUTE FreeTDM/1:1/5530 set(RFC2822_DATE=Sun, 08 Jan 2012 18:04:55 -0700) 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] EXECUTE FreeTDM/1:1/5530 export(dialed_extension=1001) 2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1091 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE FreeTDM/1:1/5530 bind_meta_app(1 b s execute_extension::dx XML features) 2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE FreeTDM/1:1/5530 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/**********.2012-01-08-18-04 -55.wav) 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 EXECUTE FreeTDM/1:1/5530 bind_meta_app(3 b s execute_extension::cf XML features) 2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE FreeTDM/1:1/5530 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2012-01-08 18:04:55.006902 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE FreeTDM/1:1/5530 set(ringback=%(2000,4000,440,480)) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [ringback]=[%(2000,4000,440,480)] EXECUTE FreeTDM/1:1/5530 set(transfer_ringback=local_stream://moh) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [transfer_ringback]=[local_stream://moh] EXECUTE FreeTDM/1:1/5530 set(call_timeout=30) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [call_timeout]=[30] EXECUTE FreeTDM/1:1/5530 set(hangup_after_bridge=true) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [hangup_after_bridge]=[true] EXECUTE FreeTDM/1:1/5530 set(continue_on_fail=true) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [continue_on_fail]=[true] EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-call_return/1001/**********) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/1001/f11ea7a0-3a5d-11e1-a157-018f03d4 5a74) EXECUTE FreeTDM/1:1/5530 set(called_party_callgroup=techsupport) 2012-01-08 18:04:55.006902 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [called_party_callgroup]=[techsupport] EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/techsupport/f11ea7a0-3a5d-11e1-a157-0 18f03d45a74) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/global/f11ea7a0-3a5d-11e1-a157-018f03 d45a74) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/techsupport/f11ea7a0-3a5d-11e1-a157-018f0 3d45a74) EXECUTE FreeTDM/1:1/5530 bridge(user/1001@xx.xx.xx.xxx) 2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-01-08 18:04:55.006902 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-01-08 18:04:55.006902 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[xx.xx.xx.xxx] 2012-01-08 18:04:55.006902 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[1001@xx.xx.xx.xxx] 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] 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 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] 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 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 2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:85 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA INIT 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 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] 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 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 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 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 2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:148 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA ROUTING 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 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] 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 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] 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 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 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 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] 2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1668 Got a FACILITY event on span 1:1 2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1697 FACILITY subcommand 2 is not implemented, ignoring 2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1700 FACILITY subcommand 2 handler returned -1 2012-01-08 18:04:55.046916 [DEBUG] ftmod_libpri.c:1703 Caught Event on span 1 11 (FACILITY) 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] 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] 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] 2012-01-08 18:04:55.126907 [NOTICE] sofia.c:5574 Ring-Ready sofia/internal/sip:1001@xx.xx.xx.xxx:52564! 2012-01-08 18:04:55.126907 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Indicating PROGRESS_MEDIA in state PROCEED 2012-01-08 18:04:55.126907 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROCEED to PROGRESS 2012-01-08 18:04:55.146908 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS 2012-01-08 18:04:55.146908 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS] 2012-01-08 18:04:55.146908 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROCEED to PROGRESS in 22ms 2012-01-08 18:04:55.146908 [ERR] ftmod_libpri.c:132 XXX Progress message requested but no information is provided 2012-01-08 18:04:55.146908 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROGRESS to PROGRESS_MEDIA 2012-01-08 18:04:55.206902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS_MEDIA 2012-01-08 18:04:55.206902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS_MEDIA] 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 2012-01-08 18:04:55.206902 [INFO] ftmod_zt.c:656 Setting echo cancel to 64 taps for 1:1 2012-01-08 18:04:55.206902 [WARNING] ftmod_zt.c:661 Echo cancel not available for 1:1 2012-01-08 18:04:55.206902 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.206902 [NOTICE] switch_ivr_originate.c:1115 Pre-Answer FreeTDM/1:1/5530! 2012-01-08 18:04:55.206902 [DEBUG] switch_channel.c:2930 (FreeTDM/1:1/5530) Callstate Change RINGING -> EARLY 2012-01-08 18:04:55.206902 [DEBUG] switch_ivr_originate.c:1164 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2012-01-08 18:04:55.206902 [DEBUG] switch_core_codec.c:116 FreeTDM/1:1/5530 Push codec L16:70 2012-01-08 18:04:55.206902 [DEBUG] switch_ivr_originate.c:1227 Play Ringback Tone [%(2000,4000,440,480)] 2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:1065 -- Hangup REQ on channel 1:1 2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:1078 [s1c1][1:1] Changed state from PROGRESS_MEDIA to TERMINATING 2012-01-08 18:04:55.226909 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for TERMINATING 2012-01-08 18:04:55.226909 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [TERMINATING] 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 2012-01-08 18:04:55.226909 [DEBUG] ftdm_io.c:5565 [s1c1][1:1] Scheduling safety hangup timer 2012-01-08 18:04:55.226909 [DEBUG] mod_freetdm.c:2416 got clear channel sig [STOP] 2012-01-08 18:04:55.226909 [DEBUG] switch_channel.c:2846 (FreeTDM/1:1/5530) Callstate Change EARLY -> HANGUP 2012-01-08 18:04:55.226909 [NOTICE] mod_freetdm.c:2441 Hangup FreeTDM/1:1/5530 [CS_EXECUTE] [MANDATORY_IE_MISSING] 2012-01-08 18:04:55.226909 [DEBUG] switch_channel.c:2869 Send signal FreeTDM/1:1/5530 [KILL] 2012-01-08 18:04:55.226909 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.246902 [DEBUG] switch_core_codec.c:141 FreeTDM/1:1/5530 Restore previous codec PCMU:0. 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 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] 2012-01-08 18:04:55.246902 [DEBUG] switch_channel.c:2869 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:52564 [KILL] 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] 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 2012-01-08 18:04:55.246902 [DEBUG] switch_ivr_originate.c:3358 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2012-01-08 18:04:55.246902 [NOTICE] switch_ivr_originate.c:2459 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL] 2012-01-08 18:04:55.246902 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL] 2012-01-08 18:04:55.246902 [INFO] mod_dptools.c:2900 Originate Failed. Cause: ORIGINATOR_CANCEL 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) 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE going to sleep 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_HANGUP 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 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 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP 2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:530 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP ENTER 2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:605 [s1c1][1:1] Changed state from TERMINATING to HANGUP 2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/internal/sip:1001@xx.xx.xx.xxx:52564 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 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 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 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] 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 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 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 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 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 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] 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 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 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] 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 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 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 2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:374 sofia/internal/sip:1001@xx.xx.xx.xxx:52564 SOFIA DESTROY 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 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 2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP] 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from TERMINATING to HANGUP in 15ms 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:929 [s1c1][1:1] Changed state from HANGUP to HANGUP_COMPLETE 2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP_COMPLETE 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP_COMPLETE] 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 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:939 [s1c1][1:1] Changed state from HANGUP_COMPLETE to DOWN 2012-01-08 18:04:55.246902 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for DOWN 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [DOWN] 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 2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2930 [s1c1][1:1] DTMF debug is already disabled 2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2962 [s1c1][1:1] No need to disable input dump 2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2993 [s1c1][1:1] No need to disable output dump 2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:2416 got clear channel sig [RELEASED] 2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:6185 Cleared call with id 1 2012-01-08 18:04:55.246902 [DEBUG] ftdm_io.c:2735 [s1c1][1:1] channel done 2012-01-08 18:04:55.246902 [DEBUG] ftmod_libpri.c:704 -- Closed channel 1:1 2012-01-08 18:04:55.246902 [DEBUG] mod_freetdm.c:624 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP EXIT 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:47 FreeTDM/1:1/5530 Standard HANGUP, cause: MANDATORY_IE_MISSING 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP going to sleep 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:393 (FreeTDM/1:1/5530) State Change CS_HANGUP -> CS_REPORTING 2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_REPORTING 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:79 FreeTDM/1:1/5530 Standard REPORTING, cause: MANDATORY_IE_MISSING 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING going to sleep 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:387 (FreeTDM/1:1/5530) State Change CS_REPORTING -> CS_DESTROY 2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-08 18:04:55.246902 [DEBUG] switch_core_session.c:1380 Session 1 (FreeTDM/1:1/5530) Locked, Waiting on external entities 2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1398 Session 1 (FreeTDM/1:1/5530) Ended 2012-01-08 18:04:55.246902 [NOTICE] switch_core_session.c:1400 Close Channel FreeTDM/1:1/5530 [CS_DESTROY] 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:491 (FreeTDM/1:1/5530) Callstate Change HANGUP -> DOWN 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:494 (FreeTDM/1:1/5530) Running State Change CS_DESTROY 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:86 FreeTDM/1:1/5530 Standard DESTROY 2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY going to sleep Full log (including loading FreeSWITCH) at http://pastebin.com/vQUHu0pR freeswitch/conf/freetdm.conf - [span zt PRI] trunk_type => T1 b-channel=1-23 d-channel=24 freeswitch/conf/autoload_confg/freetdm.conf.xml - <configuration name="freetdm.conf" description="FreeTDM Configuration"> <settings> <param name="debug" value="1"/> </settings> <libpri_spans> <span name="PRI"> <param name="node" value="cpe"/> <param name="switch" value="ni2"/> <param name="dialplan" value="XML"/> <param name="context" value="public"/> <param name="l1" value="ulaw"/> </span> </libpri_spans> </configuration> /etc/dahdi/system.conf - loadzone = us defaultzone=us dynamic=ethmf,eth0/00:50:c2:65:d7:59/0,24,1 bchan=1-23 dchan=24 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. Any help is greatly appreciated. -Adam