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
On 09.01.2012 02:33, Adam Ford wrote:
Below is what I get in the log, I highlighted in RED as soon as the call appears to start failing -
Please enable libpri debug logging (ftdm libpri debug SPAN q931_all) and capture the log output again. -- ------------------------------------------------------------------------------- Stefan Knoblich | Web: http://www.axsentis.de/ axsentis GmbH | http://oss.axsentis.de/ Eupener Str. 74, 50933 Koeln, Germany | Amtsgericht Koeln: HR B 56238 | Email: s.knoblich@axsentis.de UST-ID: DE244977565 | JID: s.knoblich@jabber.axsentis.de ------------------------------------------------------------------------------- Web: http://stkn.techmage.de/ Email: stkn@freeswitch.org IRC: #freeswitch-de @ irc.freenode.net
I am still having issues with MANDATORY_IE_MISSING on incoming calls when using FreeTDM + libpri + DAHDI + foneBridge2. Can anyone help me figure out if this is a configuration issue or a bug/incompatibility? As stated before, I am running the latest git trunk with all default/stock settings with the exception of FreeTDM configuration and minor modification to the dialplan to pass my DID to the default extension 1001. Outgoing calls are working great. Below is the debug log from FreeSWITCH with libpri debugging enabled (highlighted in RED when the call appears to start failing) - 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-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/5530) State Change CS_ROUTING -> CS_EXECUTE 2012-01-09 18:31:23.487064 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/5530) State ROUTING going to sleep 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_EXECUTE 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE 2012-01-09 18:31:23.487064 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/5530 CHANNEL EXECUTE 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/5530 Standard EXECUTE EXECUTE FreeTDM/1:1/5530 set(open=true) 2012-01-09 18:31:23.487064 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [open]=[true] EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-spymap/**********/ce58b396-3b2a-11e1-b7d4-9d287cd8d dec) 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/ce58b396-3b2a-11e1-b7d4-9d287cd8dd ec) EXECUTE FreeTDM/1:1/5530 set(RFC2822_DATE=Mon, 09 Jan 2012 18:31:23 -0700) 2012-01-09 18:31:23.487064 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/5530 SET [RFC2822_DATE]=[Mon, 09 Jan 2012 18:31:23 -0700] EXECUTE FreeTDM/1:1/5530 export(dialed_extension=1001) 2012-01-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09-18-31 -23.wav) 2012-01-09 18:31:23.487064 [INFO] switch_ivr_async.c:3179 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/**********.2012-01-09-18-31 -23.wav EXECUTE FreeTDM/1:1/5530 bind_meta_app(3 b s execute_extension::cf XML features) 2012-01-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09 18:31:23.487064 [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-09 18:31:23.487064 [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/ce58b396-3b2a-11e1-b7d4-9d287cd8 ddec) EXECUTE FreeTDM/1:1/5530 set(called_party_callgroup=techsupport) 2012-01-09 18:31:23.487064 [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/ce58b396-3b2a-11e1-b7d4-9 d287cd8ddec) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial_ext/global/ce58b396-3b2a-11e1-b7d4-9d287c d8ddec) EXECUTE FreeTDM/1:1/5530 hash(insert/xx.xx.xx.xxx-last_dial/techsupport/ce58b396-3b2a-11e1-b7d4-9d287 cd8ddec) EXECUTE FreeTDM/1:1/5530 bridge(user/1001@xx.xx.xx.xxx) 2012-01-09 18:31:23.487064 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2012-01-09 18:31:23.487064 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-01-09 18:31:23.487064 [DEBUG] switch_channel.c:1045 FreeTDM/1:1/5530 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2012-01-09 18:31:23.487064 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-01-09 18:31:23.487064 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[xx.xx.xx.xxx] 2012-01-09 18:31:23.487064 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[1001@xx.xx.xx.xxx] 2012-01-09 18:31:23.487064 [NOTICE] switch_channel.c:924 New Channel sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [ce61ab90-3b2a-11e1-b7db-9d287cd8ddec] 2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:4674 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State Change CS_NEW -> CS_INIT 2012-01-09 18:31:23.487064 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_INIT 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State INIT 2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:85 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 SOFIA INIT 2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State Change CS_INIT -> CS_ROUTING 2012-01-09 18:31:23.487064 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State INIT going to sleep 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_ROUTING 2012-01-09 18:31:23.487064 [DEBUG] switch_channel.c:1884 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Callstate Change DOWN -> RINGING 2012-01-09 18:31:23.487064 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State ROUTING 2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:148 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 SOFIA ROUTING 2012-01-09 18:31:23.487064 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-01-09 18:31:23.487064 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State ROUTING going to sleep 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_CONSUME_MEDIA 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State CONSUME_MEDIA 2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State CONSUME_MEDIA going to sleep 2012-01-09 18:31:23.487064 [DEBUG] sofia.c:5482 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:60440 entering state [calling][0] 2012-01-09 18:31:23.566904 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.566904 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.586909 [DEBUG] sofia.c:5482 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:60440 entering state [proceeding][180] 2012-01-09 18:31:23.586909 [NOTICE] sofia.c:5574 Ring-Ready sofia/internal/sip:1001@xx.xx.xx.xxx:60440! 2012-01-09 18:31:23.586909 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Indicating PROGRESS_MEDIA in state PROCEED 2012-01-09 18:31:23.586909 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROCEED to PROGRESS 2012-01-09 18:31:23.586909 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS] 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROCEED to PROGRESS in 13ms 2012-01-09 18:31:23.586909 [ERR] ftmod_libpri.c:132 XXX Progress message requested but no information is provided 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > DL-DATA request 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=5 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > Message Type: PROGRESS (3) 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=5 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.586909 [DEBUG] ftmod_libpri.c:150 > Message Type: PROGRESS (3) 2012-01-09 18:31:23.586909 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROGRESS to PROGRESS_MEDIA 2012-01-09 18:31:23.646919 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS_MEDIA 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [PROGRESS_MEDIA] 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROGRESS to PROGRESS_MEDIA in 55ms 2012-01-09 18:31:23.646919 [INFO] ftmod_zt.c:656 Setting echo cancel to 64 taps for 1:1 2012-01-09 18:31:23.646919 [WARNING] ftmod_zt.c:661 Echo cancel not available for 1:1 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > DL-DATA request 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=9 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Message Type: PROGRESS (3) 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=9 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Message Type: PROGRESS (3) 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > [1e 02 81 88] 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) 2012-01-09 18:31:23.646919 [DEBUG] ftmod_libpri.c:150 > Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] 2012-01-09 18:31:23.646919 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-09 18:31:23.646919 [NOTICE] switch_ivr_originate.c:1115 Pre-Answer FreeTDM/1:1/5530! 2012-01-09 18:31:23.646919 [DEBUG] switch_channel.c:2930 (FreeTDM/1:1/5530) Callstate Change RINGING -> EARLY 2012-01-09 18:31:23.646919 [DEBUG] switch_ivr_originate.c:1164 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2012-01-09 18:31:23.646919 [DEBUG] switch_core_codec.c:116 FreeTDM/1:1/5530 Push codec L16:70 2012-01-09 18:31:23.646919 [DEBUG] switch_ivr_originate.c:1227 Play Ringback Tone [%(2000,4000,440,480)] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < Protocol Discriminator: Q.931 (8) len=10 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent from originator) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < Message Type: DISCONNECT (69) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < [08 03 80 e0 1e] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < Cause (len= 5) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < Ext: 1 Cause: Mandatory information element is missing (96), class = Protocol Error (e.g. unknown message) (6) ] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 < Cause data 1: 1e (30) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 Received message for call 0x9ff3790 on link 0x9f8403c TEI/SAPI 0/0 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 -- Processing IE 8 (cs0, Cause) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 -- Found active call: 0x9ff3790 cref:5073 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 q931.c:8707 post_handle_q931_message: Call 5073 enters state 12 (Disconnect Indication). Hold state: Idle 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:1065 -- Hangup REQ on channel 1:1 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 q931.c:6837 q931_hangup: Hangup other cref:5073 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 q931.c:6594 __q931_hangup: ourstate Disconnect Indication, peerstate Disconnect Request, hold-state Idle 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 q931.c:5703 q931_release: Call 5073 enters state 19 (Release Request). Hold state: Idle 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > DL-DATA request 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=9 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Message Type: RELEASE (77) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Protocol Discriminator: Q.931 (8) len=9 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent to originator) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Message Type: RELEASE (77) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > [08 02 81 e0] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1) 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:150 > Ext: 1 Cause: Mandatory information element is missing (96), class = Protocol Error (e.g. unknown message) (6) ] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:1078 [s1c1][1:1] Changed state from PROGRESS_MEDIA to TERMINATING 2012-01-09 18:31:23.726904 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for TERMINATING 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [TERMINATING] 2012-01-09 18:31:23.726904 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from PROGRESS_MEDIA to TERMINATING in 0ms 2012-01-09 18:31:23.726904 [DEBUG] ftdm_io.c:5565 [s1c1][1:1] Scheduling safety hangup timer 2012-01-09 18:31:23.726904 [DEBUG] mod_freetdm.c:2416 got clear channel sig [STOP] 2012-01-09 18:31:23.726904 [DEBUG] switch_channel.c:2846 (FreeTDM/1:1/5530) Callstate Change EARLY -> HANGUP 2012-01-09 18:31:23.726904 [NOTICE] mod_freetdm.c:2441 Hangup FreeTDM/1:1/5530 [CS_EXECUTE] [MANDATORY_IE_MISSING] 2012-01-09 18:31:23.726904 [DEBUG] switch_channel.c:2869 Send signal FreeTDM/1:1/5530 [KILL] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_codec.c:141 FreeTDM/1:1/5530 Restore previous codec PCMU:0. 2012-01-09 18:31:23.726904 [DEBUG] switch_channel.c:2846 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Callstate Change RINGING -> HANGUP 2012-01-09 18:31:23.726904 [NOTICE] switch_ivr_originate.c:3182 Hangup sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL] 2012-01-09 18:31:23.726904 [DEBUG] switch_channel.c:2869 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [KILL] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_HANGUP 2012-01-09 18:31:23.726904 [DEBUG] switch_ivr_originate.c:3358 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2012-01-09 18:31:23.726904 [NOTICE] switch_ivr_originate.c:2459 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL] 2012-01-09 18:31:23.726904 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL] 2012-01-09 18:31:23.726904 [INFO] mod_dptools.c:2900 Originate Failed. Cause: ORIGINATOR_CANCEL 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:2285 FreeTDM/1:1/5530 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/5530) State EXECUTE going to sleep 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_HANGUP 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State HANGUP 2012-01-09 18:31:23.726904 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:1001@xx.xx.xx.xxx:60440 hanging up, cause: ORIGINATOR_CANCEL 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP 2012-01-09 18:31:23.726904 [DEBUG] mod_freetdm.c:530 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP ENTER 2012-01-09 18:31:23.726904 [DEBUG] mod_freetdm.c:605 [s1c1][1:1] Changed state from TERMINATING to HANGUP 2012-01-09 18:31:23.726904 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/internal/sip:1001@xx.xx.xx.xxx:60440 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 Standard HANGUP, cause: ORIGINATOR_CANCEL 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State HANGUP going to sleep 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State Change CS_HANGUP -> CS_REPORTING 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_REPORTING 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State REPORTING 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 Standard REPORTING, cause: ORIGINATOR_CANCEL 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State REPORTING going to sleep 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State Change CS_REPORTING -> CS_DESTROY 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [BREAK] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_session.c:1380 Session 2 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Locked, Waiting on external entities 2012-01-09 18:31:23.726904 [NOTICE] switch_core_session.c:1398 Session 2 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Ended 2012-01-09 18:31:23.726904 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:1001@xx.xx.xx.xxx:60440 [CS_DESTROY] 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Callstate Change HANGUP -> DOWN 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) Running State Change CS_DESTROY 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State DESTROY 2012-01-09 18:31:23.726904 [DEBUG] mod_sofia.c:374 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 SOFIA DESTROY 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:1001@xx.xx.xx.xxx:60440 Standard DESTROY 2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:1001@xx.xx.xx.xxx:60440) State DESTROY going to sleep 2012-01-09 18:31:23.786903 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP] 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from TERMINATING to HANGUP in 52ms 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:150 q931.c:6837 q931_hangup: Hangup other cref:5073 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:150 q931.c:6594 __q931_hangup: ourstate Release Request, peerstate Disconnect Request, hold-state Idle 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:929 [s1c1][1:1] Changed state from HANGUP to HANGUP_COMPLETE 2012-01-09 18:31:23.786903 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for HANGUP_COMPLETE 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [HANGUP_COMPLETE] 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from HANGUP to HANGUP_COMPLETE in 0ms 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:939 [s1c1][1:1] Changed state from HANGUP_COMPLETE to DOWN 2012-01-09 18:31:23.786903 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for DOWN 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:679 -- 1:1 STATE [DOWN] 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:687 [s1c1][1:1] Completed state change from HANGUP_COMPLETE to DOWN in 0ms 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:150 Destroying call 0x9ff3790, ourstate Release Request, peerstate Disconnect Request, hold-state Idle 2012-01-09 18:31:23.786903 [DEBUG] ftdm_io.c:2930 [s1c1][1:1] DTMF debug is already disabled 2012-01-09 18:31:23.786903 [DEBUG] ftdm_io.c:2962 [s1c1][1:1] No need to disable input dump 2012-01-09 18:31:23.786903 [DEBUG] ftdm_io.c:2993 [s1c1][1:1] No need to disable output dump 2012-01-09 18:31:23.786903 [DEBUG] mod_freetdm.c:2416 got clear channel sig [RELEASED] 2012-01-09 18:31:23.786903 [DEBUG] ftdm_io.c:6185 Cleared call with id 1 2012-01-09 18:31:23.786903 [DEBUG] ftdm_io.c:2735 [s1c1][1:1] channel done 2012-01-09 18:31:23.786903 [DEBUG] ftmod_libpri.c:704 -- Closed channel 1:1 2012-01-09 18:31:23.786903 [DEBUG] mod_freetdm.c:624 [1:1] FreeTDM/1:1/5530 CHANNEL HANGUP EXIT 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:47 FreeTDM/1:1/5530 Standard HANGUP, cause: MANDATORY_IE_MISSING 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:602 (FreeTDM/1:1/5530) State HANGUP going to sleep 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:393 (FreeTDM/1:1/5530) State Change CS_HANGUP -> CS_REPORTING 2012-01-09 18:31:23.786903 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/5530) Running State Change CS_REPORTING 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:79 FreeTDM/1:1/5530 Standard REPORTING, cause: MANDATORY_IE_MISSING 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/5530) State REPORTING going to sleep 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:387 (FreeTDM/1:1/5530) State Change CS_REPORTING -> CS_DESTROY 2012-01-09 18:31:23.786903 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/5530 [BREAK] 2012-01-09 18:31:23.786903 [DEBUG] switch_core_session.c:1380 Session 1 (FreeTDM/1:1/5530) Locked, Waiting on external entities 2012-01-09 18:31:23.786903 [NOTICE] switch_core_session.c:1398 Session 1 (FreeTDM/1:1/5530) Ended 2012-01-09 18:31:23.786903 [NOTICE] switch_core_session.c:1400 Close Channel FreeTDM/1:1/5530 [CS_DESTROY] 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:491 (FreeTDM/1:1/5530) Callstate Change HANGUP -> DOWN 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:494 (FreeTDM/1:1/5530) Running State Change CS_DESTROY 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:86 FreeTDM/1:1/5530 Standard DESTROY 2012-01-09 18:31:23.786903 [DEBUG] switch_core_state_machine.c:504 (FreeTDM/1:1/5530) State DESTROY going to sleep 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 < Protocol Discriminator: Q.931 (8) len=5 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 < TEI=0 Call Ref: len= 2 (reference 5073/0x13D1) (Sent from originator) 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 < Message Type: RELEASE COMPLETE (90) 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 -- Making new call for cref 5073 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 Received message for call 0xb6a10b50 on link 0x9f8403c TEI/SAPI 0/0 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 q931.c:6837 q931_hangup: Hangup other cref:5073 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 q931.c:6594 __q931_hangup: ourstate Null, peerstate Null, hold-state Idle 2012-01-09 18:31:23.826906 [DEBUG] ftmod_libpri.c:150 Destroying call 0xb6a10b50, ourstate Null, peerstate Null, hold-state Idle I've posted the full log (from starting FreeSWITCH to incoming call failure) at - http://pastebin.com/QaBqbCgU You can see my configuration files in the original e-mail below. Thanks in advance if anyone is able to help. This is my last attempt before settling with FreeSWITCH 1.0.6 + OpenZAP(already working in production) instead of lastest + FreeTDM. -Adam From: freeswitch-users-bounces@lists.freeswitch.org [mailto:freeswitch-users-bounces@lists.freeswitch.org] On Behalf Of Adam Ford Sent: Sunday, January 08, 2012 6:33 PM To: FreeSWITCH-users@lists.freeswitch.org Subject: [Freeswitch-users] FreeTDM [MANDATORY_IE_MISSING] 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 - <replaced with above> 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
On 13.01.2012 02:51, Adam Ford wrote:
I am still having issues with MANDATORY_IE_MISSING on incoming calls when using FreeTDM + libpri + DAHDI + foneBridge2. Can anyone help me figure out if this is a configuration issue or a bug/incompatibility?
As stated before, I am running the latest git trunk with all default/stock settings with the exception of FreeTDM configuration and minor modification to the dialplan to pass my DID to the default extension 1001. Outgoing calls are working great.
Try the attached patch, that should fix it (and hopefully doesn't have any side effects). -- ------------------------------------------------------------------------------- Stefan Knoblich | Web: http://www.axsentis.de/ axsentis GmbH | http://oss.axsentis.de/ Eupener Str. 74, 50933 Koeln, Germany | Amtsgericht Koeln: HR B 56238 | Email: s.knoblich@axsentis.de UST-ID: DE244977565 | JID: s.knoblich@jabber.axsentis.de ------------------------------------------------------------------------------- Web: http://stkn.techmage.de/ Email: stkn@freeswitch.org IRC: #freeswitch-de @ irc.freenode.net
Thank you so much for your response. I have confirmed this patch has fixed the issue, and FreeTDM is now working flawlessly with libpri + DAHDI + Redfone foneBridge2. -Adam -----Original Message----- From: Stefan Knoblich [mailto:stkn@freeswitch.org] Sent: Friday, January 13, 2012 9:06 AM To: FreeSWITCH Users Help Cc: Adam Ford Subject: Re: [Freeswitch-users] FreeTDM [MANDATORY_IE_MISSING] On 13.01.2012 02:51, Adam Ford wrote:
I am still having issues with MANDATORY_IE_MISSING on incoming calls when using FreeTDM + libpri + DAHDI + foneBridge2. Can anyone help me figure out if this is a configuration issue or a bug/incompatibility?
As stated before, I am running the latest git trunk with all default/stock settings with the exception of FreeTDM configuration and minor modification to the dialplan to pass my DID to the default extension 1001. Outgoing calls are working great.
Try the attached patch, that should fix it (and hopefully doesn't have any side effects). -- ---------------------------------------------------------------------------- --- Stefan Knoblich | Web: http://www.axsentis.de/ axsentis GmbH | http://oss.axsentis.de/ Eupener Str. 74, 50933 Koeln, Germany | Amtsgericht Koeln: HR B 56238 | Email: s.knoblich@axsentis.de UST-ID: DE244977565 | JID: s.knoblich@jabber.axsentis.de ---------------------------------------------------------------------------- --- Web: http://stkn.techmage.de/ Email: stkn@freeswitch.org IRC: #freeswitch-de @ irc.freenode.net
participants (2)
-
Adam Ford
-
Stefan Knoblich