A while back it occurred to me that the best  Unified Communications Engineers  are the ones that  best understand the language of ‘ machines’ .  The truth is, when a device develops a problem, it will try to tell you in its own way using its own language. Just as in any other form of interaction; success is rare in the absence of  being able to give expression to one’s wishes and also being able to listen. An Engineer speaks the language when he issues commands to a device using a ‘ graphical user interface’ or a  ‘ command line interface’ . An Engineer interprets/understands  the  language of machines when he is able to decipher  trace and  error logs.

So, I made up my mind that where possible, I would try to  listen first:  I decided to  look for the root causes of a problem by first taking a look at the traces and logs  before double checking the  configurations. The aim of this is simply geared towards improving my ability to understand what these devices are trying to tell me in logs and traces when something goes wrong. practice makes perfect!

I suspect someone out there shares my view that understanding logs and traces is what completes an Engineer so I am going to share this little episode  that occurred in my home lab recently.

So  a few days ago I took my personal router and switch with me to a data-center where I was carrying out a server rebuild. I had modified the configurations on my devices to replicate the client’s network but for some reason, when I got home  to do some practice labs, I was almost surprised that my MGCP gateway would not   register to my Call Manager.

It was time to explore machine language so I logged unto the voice gateway and issued the following commands:

1) Debug mgcp packets

2) Terminal monitor

3) On the call-manager, I enabled detailed traces for voice gateways and MGCP.

4)  Lastly, from the voice gateway’s global configuration  interface, I issued the commands ‘ no mgcp’ following by ‘ mgcp’ . By so doing, I was essentially restarting the MGCP process.

Here is what I saw happening on the gateway:

*Jul 6 11:23:29.324: MGCP Packet sent to 192.168.0.55:2427—>
RSIP 205478228 *@Router.homelab.com MGCP 0.1
RM: restart
<—

*Jul 6 11:23:29.332: MGCP Packet received from 192.168.0.55:2427—>
200 205478228
<—

*Jul 6 11:23:29.332: MGCP Packet received from 192.168.0.55:2427—>
AUEP 31 S0/SU3/DS1-0/1@Router.homelab.com MGCP 0.1
F: X, A, I
<—

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

In the above, we see that the process started of by the gateway (10.10.10.3) sending a RSIP ‘ Restart in progress’ message to the call-manager(192.168.0.55).

Next, we see a ‘200‘ acknowledgment  message from the Cisco call manager basically saying: ‘ I’m ok with that; thanks for letting me know’ .

Next we see an ‘Audit end point’  message (AUEP) from the call-manager asking the gateway to  provide it with a report of the current status of the ISDN trunk. The call manager is very specific because it was asking for an Audit of interface ‘S0/SU3/DS1-0/1@Router.homelab.com‘.  In human language, that means:  give me a report of the first channel (DS1-0/1) of  interface 0/3/0 at a router which has a qualified domain name of Router.homelab.com.

So far, this is normal behavior. You can double check with the  Cisco Link below which shows the registration process in graphical format.

http://www.cisco.com/en/US/tech/tk1077/technologies_tech_note09186a00801da84e.shtml#t6

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

*Jul 6 11:23:29.336: MGCP Packet sent to 192.168.0.55:2427—>
500 31 Endpt Unknown
<—

*Jul 6 11:23:29.336: MGCP Packet received from 192.168.0.55:2427—>
AUEP 32 S0/SU3/DS1-0/2@Router.homelab.com MGCP 0.1
F: X, A, I
<—

*Jul 6 11:23:29.336: MGCP Packet sent to 192.168.0.55:2427—>
500 32 Endpt Unknown
<—

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

In the first line above, we see that the voice gateway responded to the call-manager’s ‘Audit endpoint’ request with a ‘500’ endpoint unknown response.

In the next two lines, we see that the call-manager tries to ask the gateway the same question about the second  channel (DS1-0/2)on of the ISDN trunk but   once again, the gateway tells the call-manager that it does not know what it’s talking about.

In case you have not understand how to spot  the channel that an audit is being requeted for, take a look at the output below. I think it will make everything sink in:

Router# sh mgcp endpoint

Interface E1 0/3/0

ENDPOINT-NAME V-PORT SIG-TYPE ADMIN
S0/SU3/ds1-0/1@Router 0/3/0:15 none up
S0/SU3/ds1-0/2@Router 0/3/0:15 none up
S0/SU3/ds1-0/3@Router 0/3/0:15 none up

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

So at this point I already knew why my gateway was not registering  but I was curious about seeing how the call-manager would try to express the problem to me so I  collected call-manager traces and this is what I saw:

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

|MGCPHandler received msg from: 10.10.10.3
RSIP 205478228 *@Router.homelab.com MGCP 0.1
RM: restart

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

From the above we see that the call-manager received a  restart in progress(RSIP) message from the voice-gateway ‘Router.homelab.com’ which is at IP Adress 10.10.10.3.

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

In the logs below,  we see the ‘MGCP manager’; which is running on the call-manager, scrambling to figure out who device ‘Router.homelab.com ‘ is by querying the call-manager database.  In the second line below, we see that call-manager believes that the gateway is using a protocol of ‘ PRI Euro’ which runs on E1. 

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

|MGCPManager::loadDbMGCPDeviceDigitalAccessPriMatchFunc – found GwName(S0/SU3/DS1-0@Router.homelab.com

MGCPpn9d – Started. Device = S0/SU3/DS1-0@Router.homelab.com, Protocol=PRI EURO, Side = USER.

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

In the first and second line below, we see the traces confirming that the ISDN layer three  Backhaul link from the gateway to the call-manager is opened.

In the fourth line, we see that the call-manager determines that this is an MGCP trunk because the model type is 121 (MODEL TYPE = 121)

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

|MGCPBhHandler 10.10.10.3 – TCP opened and BH registered for the device

MGCPpn9d – Backhaul link OPEN for Devicename S0/SU3/DS1-0@Router.homelab.com

MGCPHandler send msg SUCCESSFULLY to: 10.10.10.3

MGCPpn9d: dn_discovery_DbDnRes – DEVICE NAME = S0/SU3/DS1-0@Router.homelab.com MODEL TYPE = 121

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Since the call-manager believes that this is an MGCP trunk (MODEL TYPE = 121)running on protocol type PRI EURO,  the call-manager will not request for an audit of a  24 channel  T1 trunk would it? it will request for an audit of a 31 channel E1 trunk that is probably running in Europe or somewhere else that uses the E1 standard.

So naturally, in the second and fourth lines below, we see  call-manager was requesting for an audit (AUED) of the  1st channel (DS1-0/1) and 31st (DS1-0/31) channel respectively. I did not added the audit request for channel 2 to 30 because it was not needed, but as can be seen in the last line of trace, the gateway’s response to every audit request was: ‘ sorry, I don’t know what you are talking about’ (500 31 Endpt Unknown)

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

|MGCPHandler send msg SUCCESSFULLY to: 10.10.10.3

AUEP 31 S0/SU3/DS1-0/1@Router.homelab.com MGCP 0.1
F: X, A, I

|MGCPHandler send msg SUCCESSFULLY to: 10.10.10.3
AUEP 60 S0/SU3/DS1-0/31@Router.homelab.com MGCP 0.1
F: X, A, I

|MGCPHandler received msg from: 10.10.10.3
500 31 Endpt Unknown

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

If you recall from the beginning of this post I said that I already knew what was wrong when the voice-gateway responded with the ‘endpoint unknown message’ to the audit  endpoint request  from the call-manager. we are about to see the reason why.

The next thing I did was to turn off all debugging on the voice-gateway by using the command: ‘ u all’ at configuration mode. However, I still had terminal monitor on.

I then logged unto the Cisco Communications Manager webpage and reset my gateway from there. I went back to the voice-gateway and this is the shortened version of what I saw:

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

*Jul  6 14:23:32.884: %SYS-5-CONFIG_I: Configured from console by console

controller E1 0/3/0
^
% Invalid input detected at^‘ marker.

pri-group timeslots 1-31 service mgcp
^
% Invalid input detected at ‘^‘ marker.

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Do you know what’s happening above?  Basically, because I had reset the voice-gateway on call-manager, a signal was sent to the voice-gateway that it should reboot the trunk and download a new set of configurations.

The gateway clearly download the new configuration because the gateway was actually trying to configure the E1 port as can be seen  in the second line of the trace output above. However, we see that the router return an error of ‘ invalid input detected.  This means that this command is not allowed.  But the question is why?   . . . lets find out.

So on the voice gateway I issued the commands ‘do sh run | in controller ‘ and ‘do sh run | in card ‘:

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Router(config)#do sh run | in controller
controller T1 0/3/0

Router(config)#do sh run | in card type
card type t1 0 3
voice-card 0

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

So from the above we can clearly see what the problem was. The Call-manager was trying to configure an E1 interface but there was no E1 interfaces on the gateway just T1.   So all along, the call manager was trying to take audit for an E1 interface that did not exist and the gateway could not register it’s MGCP ports because they were not configured as T1 on the call-manager.  Here is what I did to resolve it:

Router(config)#no card type t1 0 3

Router(config)# card type E1 0 3

Router(config)# reload

Then I reset the gateway on call-manager and everything worked perfectly.   I really hope someone has found this informative because my original thought was that this case is not blog-worthy. However, since the main focus was on understanding traces and becoming more familiar with them, I hope a greater understanding of traces  has been delivered to the readers of this post.

Cheers

Maxwell

Advertisements