[Freeswitch-users] FreeTDM [MANDATORY_IE_MISSING]
Adam Ford
lists at redbonez.net
Mon Jan 9 04:33:01 MSK 2012
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 at 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 at 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 at xx.xx.xx.xxx]
2012-01-08 18:04:55.006902 [NOTICE] switch_channel.c:924 New Channel
sofia/internal/sip:1001 at 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 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564) State INIT
2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:85
sofia/internal/sip:1001 at xx.xx.xx.xxx:52564 SOFIA INIT
2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:125
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:401
(sofia/internal/sip:1001 at 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 at 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 at 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 at xx.xx.xx.xxx:52564) State ROUTING
2012-01-08 18:04:55.006902 [DEBUG] mod_sofia.c:148
sofia/internal/sip:1001 at xx.xx.xx.xxx:52564 SOFIA ROUTING
2012-01-08 18:04:55.006902 [DEBUG] switch_ivr_originate.c:66
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:410
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.006902 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.126907 [DEBUG] sofia.c:5482 Channel
sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564) State HANGUP
2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:469 Channel
sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:52564
2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:47
sofia/internal/sip:1001 at 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 at 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 at 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 at xx.xx.xx.xxx:52564 [BREAK]
2012-01-08 18:04:55.246902 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:52564) State DESTROY
2012-01-08 18:04:55.246902 [DEBUG] mod_sofia.c:374
sofia/internal/sip:1001 at 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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120108/7367b2f3/attachment-0001.html
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list