msgbartop
msgbarbottom

21 Apr 16 PRI Error – L2IF_SendPkt Failed

Voice PRI Error on Cisco Router – TEI_ASSIGNED – **ERROR**: L2IF_SendPkt: idb is NULL – **ERROR**: process_rxdata:L2IF_SendPkt Failed

Recently I ran into a voice PRI issue. Customer was unable to make any calls and the command show isdn status displayed the following result:

Global ISDN Switchtype = primary-ni
ISDN Serial0/1/0:23 interface
dsl 0, interface ISDN Switchtype = primary-ni
Layer 1 Status:
ACTIVE
Layer 2 Status:
TEI = 0, Ces = 1, SAPI = 0, State = TEI_ASSIGNED
Layer 3 Status:
0 Active Layer 3 Call(s)
Active dsl 0 CCBs = 0
The Free Channel Mask: 0x807FFFFF
Number of L2 Discards = 0, L2 Session ID = 33
Total Allocated ISDN CCBs = 0

After reviewing everything in the Cisco Call Manager and physical connectivity as well as verifying that circuit is good I decided to run a debug with the following command. debug isdn q921. I received the following output:

Apr 5 15:08:15.976: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:15.976: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:15.976: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:16.980: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:16.980: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:16.980: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:17.984: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:17.984: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:17.984: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:19.036: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:19.036: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:19.036: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:30.028: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:30.028: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:30.028: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:31.032: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:31.032: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:31.032: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:32.036: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:32.036: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:32.036: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed Apr 5 15:08:33.036: ISDN Se0/1/0:23 Q921: User RX <- SABMEp sapi=0 tei=0 Apr 5 15:08:33.036: ISDN Se0/1/0:23 **ERROR**: L2IF_SendPkt: idb is NULL Apr 5 15:08:33.036: ISDN Se0/1/0:23 **ERROR**: process_rxdata:L2IF_SendPkt Failed

After some research and looking at the router config this ended up being the culprit:

interface Serial0/1/0:23
no ip address
encapsulation hdlc
isdn switch-type primary-ni
isdn incoming-voice voice
isdn bind-l3 ccm-manager (THIS COMMAND WAS MISSING)
no cdp enable

After I added that command isdn bind-l3 ccm-manager back under the interface calls started to work and my show isdn status returned to MULTIPLE_FRAME_ESTABLISHED. You can see actually between the two results working one shows that q.931 is backhauled to CCM Manager however non working one does not say that.

Global ISDN Switchtype = primary-ni

%Q.931 is backhauled to CCM MANAGER 0x0003 on DSL 0. Layer 3 output may not apply

ISDN Serial0/1/0:23 interface
dsl 0, interface ISDN Switchtype = primary-ni
L2 Protocol = Q.921 0x0000 L3 Protocol(s) = CCM MANAGER 0x0003
Layer 1 Status:
ACTIVE
Layer 2 Status:
TEI = 0, Ces = 1, SAPI = 0, State = MULTIPLE_FRAME_ESTABLISHED
Layer 3 Status:
0 Active Layer 3 Call(s)
Active dsl 0 CCBs = 0
The Free Channel Mask: 0x807FFFFF
Number of L2 Discards = 0, L2 Session ID = 33
Total Allocated ISDN CCBs = 0

Tags: , , ,

24 Dec 13 Testing dial tone and Outbound calling from Cisco Router and FXO Card

Dial tone and Outbound calling – Cisco Router/FXO Card

Recently I had a need to test and determine if there was a dial tone on the Cisco FXO Card installed into a Cisco 2911 router. I knew that telco terminated the pots lines on the 66 block but I did not know if they were plugged into the Cisco FXO card. I did not have any one onsite to give me a visual confirmation. So I found out about couple of cool debug commands to accomplish this:

debug vpm signal
debug vpm all

Here are the steps I took:

  • First I used a test Cisco IP phoneon my desk and set it up with this offices extension in Cisco Call Manager
  • Next I setup the debug commands debug vpm all on the router with term mon
  • Next I tried to dial out from my test phone and since the Cisco Call Manager was setup to use the FXO card for the calling, it tried to dial out using one of the FXO ports
  • Now take a look at the debug message from the Cisco Router

#htsp_allocate_if —

Nov 27 10:31:46.468: HTSP endpoint_info=aaln/S0/SU0/0, type=2, under_specified=0,
service_type=2htsp_allocate_if: MATCH!

Nov 27 10:31:46.472: htsp_timer_stop3 htsp_setup_req
Nov 27 10:31:46.472: Orig called num:16152324144
Nov 27 10:31:46.472: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
Nov 27 10:31:46.472: [0/0/0] set signal state = 0xC timestamp = 0
Nov 27 10:31:46.472: dsp_set_sig_state: [0/0/0] packet_len=12 channel_id=128 packet_id=39 state=0xC timestamp=0x0
Nov 27 10:31:46.472: TGRM: reg_invoke_tgrm_call_update(0, 0, 0, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
Nov 27 10:31:46.472: htsp_timer – 1300 msec
Nov 27 10:31:46.728: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected
Nov 27 10:31:46.728: htsp_timer2 – 1000 msec
Nov 27 10:31:46.728: htsp_timer_stop
Nov 27 10:31:47.728: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER2]fxols_power_den_disc
Nov 27 10:31:47.728: htsp_timer_stop
Nov 27 10:31:47.728: htsp_timer_stop2
Nov 27 10:31:47.728: [0/0/0] set signal state = 0x4 timestamp = 0
Nov 27 10:31:47.728: dsp_set_sig_state: [0/0/0] packet_len=12 channel_id=128 packet_id=39 state=0x4 timestamp=0x0
Nov 27 10:31:47.728: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Codec htsp_release_req: cause 34, no_onhook 0
Nov 27 10:31:47.728: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_RELEASE_REQ]fxols_onhook_release
Nov 27 10:31:47.728: TGRM: reg_invoke_tgrm_call_update(0, 0, 0, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
Nov 27 10:31:47.728: flex_dsprm_close_cleanuphtsp_allocate_if —

Nov 27 10:31:47.780: HTSP endpoint_info=aaln/S0/SU0/1, type=2, under_specified=0,
service_type=2htsp_allocate_if: MATCH!

If you look at lines above you will notice that it clearly did not get a dial tone and hence my called failed. With this information I was able to verify if someone connected the cables from the 66 block to the Cisco FXO Card. I could have also used this same technique to see if there was dial tone on the pots lines on the 66 block. In case there is no butt set is available

Tags: , , , ,

19 Dec 13 Cisco Voice Gateway not Re Registering with Cisco Call Manager

Cisco Voice Gateway lost registration with Cisco Call Manager and not re registering

So VoIP is a whole new world to me and in the last two months I have learnt a whole lot. Pretty interesting stuff especially once you know it obviously lol. But troubleshooting can be a pain at times. Recently one of the Cisco router with a PRI lost its registration with the Cisco Call Manager – CUCM. None of the phones were working for outbound dialing however local extension dialing was working. When I logged into the Cisco Router and issued the following command: show ccm. I noticed that it is going back and forth trying to register with the Primary and Backup Cisco Call Manager. I looked at the settings on the Cisco Router and all VoIP related config was right. I tried to do no mgcp and then mgcp still no use. Then I started to run a debug to see what is happening and hopefully debug will give me some indication on the issue. Following commands were issued on the router:

  • debug mgcp events
  • debug mgcp errors
  • term mon

Here is what I saw in the log:

Dec 18 13:42:30.080: S0/SU0/DS1-0/* mgcp_endpt_parent_redirected: parent S0/SU0/DS1-0/*, child S0/SU0/DS1-0/23
Dec 18 13:42:30.080: S0/SU0/DS1-0/23 mgcp_endpt_set_notified_entity:
Dec 18 13:42:30.080: S0/SU0/DS1-0/23 mgcp_endpt_set_notified_entity:ne 10.206.110.20:2427, ne addr 10.206.110.20:2427
Dec 18 13:42:30.080: S0/SU0/DS1-0/23 mgcp_endpt_set_call_agent:
Dec 18 13:42:30.080: S0/SU0/DS1-0/23 mgcp_endpt_redirect_children:
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.080: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=4, conn_mode=3
Dec 18 13:42:30.084: mgcp_is_transient: callp->state=0, conn_mode=0
Dec 18 13:42:30.084: MGCP sys msg: (15)
Dec 18 13:42:30.084: xlate sys msg: (15, 4539B688)
Dec 18 13:42:30.084: sys msg values: (INVALID MGCP EVENT, 0, , 1108831796, CALL_IDLE)
Dec 18 13:42:30.084: process mgcp_handle_cmapp_event
Dec 18 13:42:30.084: mgcp_cmapp_send_rsip: Send-RSIP: Sending gw host is XYZ1-RTR-01.mydomain.com, endpt is *
Dec 18 13:42:30.084: mgcp_cmapp_send_rsip_to_callmgr: Send RSIP – Pass-in: ipaddr=10.206.110.20 ca_port=2427
Dec 18 13:42:30.084: * mgcp_root_get_profile:
Dec 18 13:42:30.084: * mgcp_send_rsip_msg:
Dec 18 13:42:30.084: * mgcp_endpt_record_rsip:
Dec 18 13:42:30.084: * mgcp_send_rsip_msg: Manually recroding RSIP method
Dec 18 13:42:30.084: * mgcp_endpt_record_rsip:
Dec 18 13:42:30.084: * mgcp_enq_retx_rsip_msg
Dec 18 13:42:30.084: mgcp_add_trans_id_rec: Add trans id (689668931, 46CBEB70) record
Dec 18 13:42:30.084: mgcp_stw_timer_start timer type 0, duration 500
Dec 18 13:42:30.652: MGC stat – 10.202.110.36, total=340539, succ=340048, failed=146
Dec 18 13:42:30.652: mgcpapp_process_mgcp_msg :
Dec 18 13:42:30.660: * mgcp_msg_ack
Dec 18 13:42:30.660: MGC stat – 10.202.110.36, total=340539, succ=340049, failed=146
Dec 18 13:42:30.660: * mgcp_check_for_redirection: endpt * was not redirected
Dec 18 13:42:30.660: [S] mgcp_msg_ack:6166,Updating (*)=10.202.110.36
Dec 18 13:42:30.660: * mgcp_msg_ack: Removing msg : RSIP 689668929 *@XYZ1-RTR-01.mydomain.com MGCP 0.1
RM: graceful
Dec 18 13:42:30.664: * mgcp_msg_ack: Setting the restart method to NONE
Dec 18 13:42:30.664: mgcpapp_process_socket
Dec 18 13:42:30.664: MGC stat – 10.206.110.20, total=313, succ=169, failed=143
Dec 18 13:42:30.664: mgcpapp_process_mgcp_msg :
Dec 18 13:42:30.664: * mgcp_msg_ack
Dec 18 13:42:30.664: MGC stat – 10.206.110.20, total=313, succ=169, failed=144
Dec 18 13:42:30.664: * mgcp_check_for_redirection: endpt * was not redirected
Dec 18 13:42:30.664: * mgcp_msg_ack: Removing msg : RSIP 689668931 *@XYZ1-RTR-01.mydomain.com MGCP 0.1
RM: restart
Dec 18 13:42:30.664: * mgcp_msg_ack: Setting the restart method to NONE
Dec 18 13:42:30.664: mgcpapp_process_socket
Dec 18 13:42:30.960: unreachable detected
Dec 18 13:42:30.960: mgcp_cr_and_init_evt_node:$$$ the node pointer 46FA4428

After looking at the debug I noticed that the registration was failing for the host “XYZ1-RTR-01.mydomain.com”. When I looked in the Cisco Call Manager I noticed that the registered name was “XYZ-RTR-01.mydomain.com”. So since the host name of the Cisco Voice Gateway hence it was no longer valid in the Cisco Call Manager. I simply updated the name in Cisco Call Manager and the Cisco Voice Gateway successfully re registered with the Cisco Call Manager – CUCM.

Tags: , , , , , , , ,

WordPress SEO