[Freeswitch-users] FreeTDM [MANDATORY_IE_MISSING]
Adam Ford
lists at redbonez.net
Fri Jan 13 04:51:59 MSK 2012
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 at 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 at xx.xx.xx.xxx]
2012-01-09 18:31:23.487064 [NOTICE] switch_channel.c:924 New Channel
sofia/internal/sip:1001 at 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 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:60440) State INIT
2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:85
sofia/internal/sip:1001 at xx.xx.xx.xxx:60440 SOFIA INIT
2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:125
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:401
(sofia/internal/sip:1001 at 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 at 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 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:410
(sofia/internal/sip:1001 at xx.xx.xx.xxx:60440) State ROUTING
2012-01-09 18:31:23.487064 [DEBUG] mod_sofia.c:148
sofia/internal/sip:1001 at xx.xx.xx.xxx:60440 SOFIA ROUTING
2012-01-09 18:31:23.487064 [DEBUG] switch_ivr_originate.c:66
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.487064 [DEBUG] switch_core_state_machine.c:410
(sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.586909 [DEBUG] sofia.c:5482 Channel
sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:60440) State HANGUP
2012-01-09 18:31:23.726904 [DEBUG] mod_sofia.c:469 Channel
sofia/internal/sip:1001 at 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 at xx.xx.xx.xxx:60440
2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:47
sofia/internal/sip:1001 at 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 at 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 at 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 at xx.xx.xx.xxx:60440 [BREAK]
2012-01-09 18:31:23.726904 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at xx.xx.xx.xxx:60440) State DESTROY
2012-01-09 18:31:23.726904 [DEBUG] mod_sofia.c:374
sofia/internal/sip:1001 at 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 at 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 at 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 at lists.freeswitch.org
[mailto:freeswitch-users-bounces at lists.freeswitch.org] On Behalf Of Adam
Ford
Sent: Sunday, January 08, 2012 6:33 PM
To: FreeSWITCH-users at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120112/079cea99/attachment-0001.html
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list