outbound through MGCP FXO

satish rawat · ‎10-27-2012

This issue is driving me to crazy...inbound on a mgcp fxo works fine no issues...when trying to make a outbound call through FXO port ( individually or using a Route list) it fails with lot of mgcp garbage in debug.

attached is debug mgcp events captured while make a outboud call

BC-PEN-VGW-01#

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_setup_per_call_data(2604):[lvl=1]mgcpapp_setup_per_call_data: callp: 319E8130, vdbptr: 30EF4E58, state: CALL_IDLE

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(451):[lvl=0]Entered

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(466):[lvl=1]ne 172.16.118.21:2427

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_mgcp_event(2735):[lvl=1]Processing Incoming Message [CRCX 2957]

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2675):[lvl=1]Msg In-Progress(Active) [INVVERB 0], await_ev=0,queued=0x0

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_process_deferred_queue(3546):[lvl=0]Entered

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_store_endpt_and_ntfy_entity_name(4829):[lvl=0]Entered

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:30.800: //1198/450734B8821C/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_idle_crcx(6155):[lvl=2]callp(0x319E8130), current state CALL_IDLE, event EV_CREATE_CONN

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_init_modem_relay_params(118):[lvl=0]modem-relay-enabled=0, mr-gw-xid=0

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_idle_crcx(6241):[lvl=0]calls mgcp_allocate_if()

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_idle_crcx(6286):[lvl=1]get capability

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 80 evtnode->evt_name: 55

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 80 evtnode->evt_name: 56

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 40 evtnode->evt_name: 32

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 80 evtnode->evt_name: 107

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_idle_crcx(6373):[lvl=0]Default aal2 vc = 0 1-pvc,2-svc

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_trans_kpstseq_to_anidnis(221):[lvl=0]Going to traverse the Sig event list

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_setup_telephony_leg(9741):[lvl=1]Entered. voce-callp=0x319E8130, vox_call_exist=0

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_is_seizure_possible(9583):[lvl=1]voice_callp = 0x319E8130

Oct 27 21:59:30.800: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_is_packet_cable_supported(2686):[lvl=0]endpt aaln/S0/SU1/0

Oct 27 21:59:30.800: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5009):[lvl=0]calling mgcp_select_codec

Oct 27 21:59:30.800: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_select_sse_nse_payload_and_modem_relay_params(481):[lvl=1]Originating side. Select the configured values

Oct 27 21:59:30.800: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_nse_payload(2247):[lvl=0]Entered

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_nse_payload(2268):[lvl=1]Orig. side CRCX. Selecting NSE payload type 100

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_sse_payload(2533):[lvl=0]Entered

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_sse_payload(2560):[lvl=0]Orig. side CRCX. Selecting SSE payload type 118

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_sprt_payload(144):[lvl=0]Entered

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_sprt_payload(169):[lvl=1]Orig. side CRCX. Selecting SPRT payload type 120

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_nte_select_dtmf_relay(662):[lvl=1]

mgcp_nte_select_dtmf_relay - LCO:1, SDP:0, lc_nte_list:0, sdp_nte_list:0

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_nte_select_dtmf_relay_using_config_rules(610):[lvl=0]OUT: mode/codec = 6/0

Oct 27 21:59:30.804: //-1/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_select_nte(1191):[lvl=1]

Old NTE:

New NTE

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5187):[lvl=1]selected codec 1

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5242):[lvl=0]IP Precedence: RTP=0x0 RTCP=0x68

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5454):[lvl=1]NSE payload=100

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5600):[lvl=2]MP or MR enabled by config. Enabling modem tone detection

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/set_up_voip_call_leg(5633):[lvl=1]Behavior CLI negotiate-nse disabled, or remote NSE support indicated, or CA-T38 FAX. So not explicitly disabling FAX tone detection

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_CONNECTING, event EV_CREATE_CONN

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2710):[lvl=0]return value = 0

Oct 27 21:59:30.804: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcpapp_process_ccapi_ev(1860):[lvl=1]CCAPI event=9-CC_EV_CALL_CONNECTED state=CALL_CONNECTING major=5-EV_CALL_CONNECT minor=141- pkg=615964564

Oct 27 21:59:30.804: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E7C60)

Oct 27 21:59:30.804: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_call_pre_conference(235):[lvl=2]callp(0x319E7C60), current state CALL_CONNECTING, event EV_CALL_CONNECT

Oct 27 21:59:30.804: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_call_connect(8643):[lvl=2]callp(0x319E7C60), current state CALL_CONNECTING, event EV_CALL_CONNECT

Oct 27 21:59:30.804: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E7C60), new state CALL_CONFERENCING, event EV_CALL_CONNECT

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_ccapi_ev(1860):[lvl=1]CCAPI event=23-CC_EV_CALL_PROCEEDING state=CALL_CONNECTING major=9-EV_CALL_PROCEED minor=141- pkg=615964564

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_call_proceeding(6654):[lvl=2]callp(0x319E8130), current state CALL_CONNECTING, event EV_CALL_PROCEED

Oct 27 21:59:30.804: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_CONNECTING, event EV_CALL_PROCEED

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_ccapi_ev(1860):[lvl=1]CCAPI event=12-CC_EV_CALL_DISCONNECTED state=CALL_CONNECTING major=11-EV_ON_HOOK minor=35- pkg=64

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_call_setup_failed(5263):[lvl=2]callp(0x319E8130), current state CALL_CONNECTING, event EV_ON_HOOK

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_disconnect_call_leg(4276):[lvl=2]Releasing CAC

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_disconnect_call_leg(4342):[lvl=0]O.K. call_id=1201

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_free_local_dyn_nse_payload(2137):[lvl=0]local NSE payload 100, configured NSE payload = 100

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_free_local_dyn_nse_payload(2150):[lvl=0]Payload bitmask after free = 0x6F400013

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_disconnect_call_leg(4276):[lvl=2]Releasing CAC

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/is_mgcp_endpt_offhook(6292):[lvl=1]hook_state is 0

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_disconnect_call_leg(4342):[lvl=0]O.K. call_id=1200

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_is_endpt_black_phone(5090):[lvl=0]voice_callp = 0x319E8130

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_disconnect_call_leg(4367):[lvl=0]resetting the waiting_for_shu to FALSE

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_send_and_enqueue_ack(2999):[lvl=0]Entered

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/enqueue_ack(624):[lvl=1]enqueue_ack: ackqhead=0, ackqtail=0, ackp=41834180, msg=2BBD0FE0

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_process_quarantine_after_ack(4069):[lvl=0]ack_code=403

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_IDLE, event EV_ON_HOOK

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcpapp_process_ccapi_ev(1860):[lvl=1]CCAPI event=13-CC_EV_CALL_DISCONNECT_DONE state=CALL_DISCONNECTING major=8-EV_CALL_DISCONNECT minor=141- pkg=615964564

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E7C60)

Oct 27 21:59:32.056: //1201/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOIP>/mgcp_call_disconnected(5447):[lvl=2]callp(0x319E7C60), current state CALL_DISCONNECTING, event EV_CALL_DISCONNECT

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_setup_per_call_data(2604):[lvl=1]mgcpapp_setup_per_call_data: callp: 319E8130, vdbptr: 30EF4E58, state: CALL_IDLE

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(451):[lvl=0]Entered

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(466):[lvl=1]ne 172.16.118.21:2427

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_mgcp_event(2735):[lvl=1]Processing Incoming Message [DLCX 2958]

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2675):[lvl=1]Msg In-Progress(Active) [INVVERB 2957], await_ev=0,queued=0x0

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_process_deferred_queue(3546):[lvl=0]Entered

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_store_endpt_and_ntfy_entity_name(4829):[lvl=0]Entered

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:32.056: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_idle_dlcx(4849):[lvl=2]callp(0x319E8130), current state CALL_IDLE, event EV_DELETE_CONN

Oct 27 21:59:32.056: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_send_and_enqueue_ack(2999):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/enqueue_ack(624):[lvl=1]enqueue_ack: ackqhead=41834180, ackqtail=41834180, ackp=41834128, msg=2BBD1720

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_process_quarantine_after_ack(4069):[lvl=0]ack_code=250

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_IDLE, event EV_DELETE_CONN

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2710):[lvl=0]return value = 1

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_ccapi_ev(1860):[lvl=1]CCAPI event=13-CC_EV_CALL_DISCONNECT_DONE state=CALL_IDLE major=21-INVALID MGCP EVENT minor=141- pkg=615964564

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_ccapi_ev(1873):[lvl=1]MGCP ccapi invalid ev=13-CC_EV_CALL_DISCONNECT_DONE major=21-INVALID MGCP EVENT minor=141- pkg=615964564

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_setup_per_call_data(2604):[lvl=1]mgcpapp_setup_per_call_data: callp: 319E8130, vdbptr: 30EF4E58, state: CALL_IDLE

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(451):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(466):[lvl=1]ne 172.16.118.21:2427

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_mgcp_event(2735):[lvl=1]Processing Incoming Message [RQNT 2959]

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2675):[lvl=1]Msg In-Progress(Active) [DLCX 0], await_ev=0,queued=0x0

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_process_deferred_queue(3546):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_store_endpt_and_ntfy_entity_name(4829):[lvl=0]Entered

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 40 evtnode->evt_name: 32

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_send_and_enqueue_ack(2999):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/enqueue_ack(624):[lvl=1]enqueue_ack: ackqhead=41834180, ackqtail=41834128, ackp=418340D0, msg=2BBD048C

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_process_quarantine_after_ack(4069):[lvl=0]ack_code=200

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_IDLE, event EV_NOTIFY_REQ

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2710):[lvl=0]return value = 0

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_setup_per_call_data(2604):[lvl=1]mgcpapp_setup_per_call_data: callp: 319E8130, vdbptr: 30EF4E58, state: CALL_IDLE

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(451):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_endpt_get_notified_entity(466):[lvl=1]ne 172.16.118.21:2427

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_process_mgcp_event(2735):[lvl=1]Processing Incoming Message [RQNT 2960]

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2675):[lvl=1]Msg In-Progress(Active) [INVVERB 2959], await_ev=0,queued=0x0

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_process_deferred_queue(3546):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_store_endpt_and_ntfy_entity_name(4829):[lvl=0]Entered

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(554):[lvl=0]MGCP:calling FSM- callp(319E8130)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5720):[lvl=0]-- mgcp_find_evt_in_mask evtnode->package_bit_map: 40 evtnode->evt_name: 32

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_is_supported_ev(5707):[lvl=0](begin)

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_send_and_enqueue_ack(2999):[lvl=0]Entered

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/enqueue_ack(624):[lvl=1]enqueue_ack: ackqhead=41834180, ackqtail=418340D0, ackp=41833F18, msg=2BBD187C

Oct 27 21:59:32.060: //-1/xxxxxxxxxxxx/MGCP/mgcp_process_quarantine_after_ack(4069):[lvl=0]ack_code=200

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcp_invoke_app_sm(590):[lvl=2]MGCP:FSM done- callp(319E8130), new state CALL_IDLE, event EV_NOTIFY_REQ

Oct 27 21:59:32.060: //1200/6B3ADE19821D/MGCP|aaln/S0/SU1/0|-1|-1/<VOICE>/mgcpapp_invoke_mgcp_sm(2710):[lvl=0]return value = 0\

Robert Thomas · ‎10-28-2012

debug mgcp packets

debug vpm signal

For us to be able to troubleshoot this effectively.

satish rawat · ‎10-28-2012

loop staRt

Oct 28 13:55:40.460: htsp_timer_stop3 htsp_setup_req
Oct 28 13:55:40.460: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]                                                  fxols_onhook_setup
Oct 28 13:55:40.460: [0/1/0] set signal state = 0xC timestamp = 0
Oct 28 13:55:40.460: htsp_timer - 1300 msec
Oct 28 13:55:40.712: htsp_process_event: [0/1/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG                                                  _1100]fxols_power_denial_detected
Oct 28 13:55:40.712: htsp_timer2 - 1000 msec
Oct 28 13:55:40.712: htsp_timer_stop
Oct 28 13:55:41.712: htsp_process_event: [0/1/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EV                                                  ENT_TIMER2]fxols_power_den_disc
Oct 28 13:55:41.712: htsp_timer_stop
Oct 28 13:55:41.712: htsp_timer_stop2
Oct 28 13:55:41.712: [0/1/0] set signal state = 0x4 timestamp = 0
Oct 28 13:55:41.712: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_HTSP_RELEASE_RE                                                  Q]fxols_onhook_release

ground start

Oct 28 14:15:25.475: htsp_timer_stop3 htsp_setup_req
Oct 28 14:15:25.475: htsp_process_event: [0/1/0, FXOGS_ONHOOK, E_HTSP_SETUP_REQ]fxogs_onhook_setup
Oct 28 14:15:25.475: [0/1/0] set signal state = 0x0 timestamp = 0
Oct 28 14:15:25.475: htsp_timer - 10000 msec
Oct 28 14:15:25.651: htsp_process_event: [0/1/0, FXOGS_WAIT_TIP_GROUND, E_DSP_SIG_0110]
Oct 28 14:15:35.475: htsp_process_event: [0/1/0, FXOGS_WAIT_TIP_GROUND, E_HTSP_EVENT_TIMER]fxogs_offhook_disc
Oct 28 14:15:35.475: htsp_timer_stop
Oct 28 14:15:35.475: [0/1/0] set signal state = 0x4 timestamp = 0
Oct 28 14:15:35.475: htsp_timer - 2000 msec
Oct 28 14:15:35.475: htsp_process_event: [0/1/0, FXOGS_ONHOOK, E_HTSP_RELEASE_REQ]fxogs_onhook_release
Oct 28 14:15:35.475: htsp_timer_stop2
Oct 28 14:15:35.475: htsp_timer_stop3
Oct 28 14:15:35.747: htsp_process_event: [0/1/0, FXOGS_ONHOOK, E_DSP_SIG_0110]
Oct 28 14:15:35.747: fxogs_line_reversal_clid_wait. On_hook line reversal detected possibily due to crossed cable
Oct 28 14:15:37.475: htsp_process_event: [0/1/0, FXOGS_ONHOOK, E_HTSP_EVENT_TIMER]

csim start 4869957

Oct 28 14:30:44.759: htsp_timer_stop3 htsp_setup_req
Oct 28 14:30:44.759: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
Oct 28 14:30:44.759: [0/1/0] set signal state = 0xC timestamp = 0
Oct 28 14:30:44.759: htsp_timer - 1300 msec
Oct 28 14:30:45.015: htsp_process_event: [0/1/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected
Oct 28 14:30:45.015: htsp_timer2 - 1000 msec
Oct 28 14:30:45.015: htsp_timer_stop
Oct 28 14:30:46.015: htsp_process_event: [0/1/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER2]fxols_power_den_disc
Oct 28 14:30:46.015: htsp_timer_stop
Oct 28 14:30:46.015: htsp_timer_stop2
Oct 28 14:30:46.015: [0/1/0] set signal state = 0x4 timestamp = 0
Oct 28 14:30:46.015: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_HTSP_RELEASE_REQ]fxols_onhook_release