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_number})

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}.${strftime(%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_number})

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-018f03d45a74)

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-018f03d45a74)

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-018f03d45a74)

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-018f03d45a74)

EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/global/f11ea7a0-3a5d-11e1-a157-018f03d45a74)

EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/techsupport/f11ea7a0-3a5d-11e1-a157-018f03d45a74)

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] 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 –

</settings>

<libpri_spans>

</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