MGCP constantly deletes inbound calls

oldcreek12 · ‎01-06-2009

Hi, all,

I have MGCP gateway C2801 in UK remote office which has 4 FXO ports, I want to route local UK phone number assigned to one FXO port to one VoIP phone which has US phone number, the US phone number was assigned as attendant number of one POTS line.

When call comes in, calling side hears short "dudu" beeps, while VoIP phone (7940) sees the incoming call, flashes but no ringing. Debug MGCP packet shows that CUCM is constantly creating and deleting the connections. I have the MGCP packet debug output attached, appreciate that if somebody and spot the problem. Thanks a lot.

oldcreek12 · ‎01-06-2009

This is the show mgcp connection output when call is coming in,

uk-srst#sh mgcp connection

Endpoint Call_ID(C) Conn_ID(I) (P)ort (M)ode (S)tate (CO)dec (E)vent[SIFL] (R)esult[EA] (ME)dia

1. aaln/S0/SU0/0 C=,260,-1 I=0x0 P=0,0 M=0 S=9,0 CO=0 E=1,10,3,10 R=0,0 ME=0

LEGEND:

Mode : 0=INVALID, 1=SENDONLY, 2=RECVONLY, 3=SENDRECV, 4=INACTIVE, 5=LOOPBACK,

6=CONTTEST, 7=DATA, 8=NETWLOOP, 9=NETWTEST, 10=CONFRNCE

State : 0=IDLE, 1=SETTING, 2=CONNECTING, 3=CONFERENCING, 4=ACTIVE, 5=CONF_DESTROYING,

6=DISCONNECTING, 7=INACTIVE, 8=VOICE_CONNECTING, 9=VOICE_ACTIVE, 10=CONF_DISSOCIATING,

11=CALLLEGS_DISSOCIATED, 12=HP_CONNECTING, 13=HP_CONNECTED, 14=HP_CONFERENCING,

15=HP_ACTIVE, 16=VOIP_CONF_DESTROY, 17=ERROR, 18=CONNECTING_INACTIVE,

19=CONF_DESTROYING_INACTIVE, 20=CONT_TEST, 21=SETUP_WAIT, 22=WAIT_NSE_SENT,

23=TWC_ACTIVE, 24=WAIT_STATE, 25=HANDOVER

Codec : 1=PCMU, 2=PCMA, 3=G726_32K, 4=G726_24K, 5=G726_16K, 6=G729, 7=G729_A, 8=G729_B, 9=G729_B_LC,

10=G728, 11=G723, 12=G7231_HIGH_RATE, 13=G7231_A_HIGH_RATE, 14=G7231_LOW_RATE,

15=G7231_A_LOW_RATE, 16=GSM_FR, 17=GSM_HR, 18=GSM_EFR, 19=GSM_EHR, 20=G729_A_B

128=CLEAR_CHANNEL, 129=NSE, 130=XNSE, 131=NTE, 132=T38, 133=MODEM_RELAY

uk-srst#sh mgcp connection

Endpoint Call_ID(C) Conn_ID(I) (P)ort (M)ode (S)tate (CO)dec (E)vent[SIFL] (R)esult[EA] (ME)dia

1. aaln/S0/SU0/0 C=A0000000028962cd000000F5,284,285 I=0x1D P=19032,0 M=2 S=4,4 CO=1 E=3,10,3,3 R=0,0 ME=0

LEGEND:

Mode : 0=INVALID, 1=SENDONLY, 2=RECVONLY, 3=SENDRECV, 4=INACTIVE, 5=LOOPBACK,

6=CONTTEST, 7=DATA, 8=NETWLOOP, 9=NETWTEST, 10=CONFRNCE

State : 0=IDLE, 1=SETTING, 2=CONNECTING, 3=CONFERENCING, 4=ACTIVE, 5=CONF_DESTROYING,

6=DISCONNECTING, 7=INACTIVE, 8=VOICE_CONNECTING, 9=VOICE_ACTIVE, 10=CONF_DISSOCIATING,

11=CALLLEGS_DISSOCIATED, 12=HP_CONNECTING, 13=HP_CONNECTED, 14=HP_CONFERENCING,

15=HP_ACTIVE, 16=VOIP_CONF_DESTROY, 17=ERROR, 18=CONNECTING_INACTIVE,

19=CONF_DESTROYING_INACTIVE, 20=CONT_TEST, 21=SETUP_WAIT, 22=WAIT_NSE_SENT,

23=TWC_ACTIVE, 24=WAIT_STATE, 25=HANDOVER

Codec : 1=PCMU, 2=PCMA, 3=G726_32K, 4=G726_24K, 5=G726_16K, 6=G729, 7=G729_A, 8=G729_B, 9=G729_B_LC,

10=G728, 11=G723, 12=G7231_HIGH_RATE, 13=G7231_A_HIGH_RATE, 14=G7231_LOW_RATE,

15=G7231_A_LOW_RATE, 16=GSM_FR, 17=GSM_HR, 18=GSM_EFR, 19=GSM_EHR, 20=G729_A_B

128=CLEAR_CHANNEL, 129=NSE, 130=XNSE, 131=NTE, 132=T38, 133=MODEM_RELAY

And debug mgcp errors reveals that:

uk-srst#

*Jan 7 01:18:49.496: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:50.096: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:52.388: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:52.980: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:55.244: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:55.848: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:58.144: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pkt->mgcp_parm_lines 0x00000000)

*Jan 7 01:18:58.744: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(828):[lvl=2]Invalid parameter (pkt 0x6688C660 pk

oldcreek12 · ‎01-06-2009

Here is CUCM trace:

01/06/2009 17:38:37.890 CCM|<:STANDALONECLUSTER><:10.1.9.6><:2><:MGCPENDPOINT><:AALN>0@uk-srst.mycompany.local><:><:ALL><:FFFF>

01/06/2009 17:38:37.890 CCM|MGCPHandler send msg SUCCESSFULLY to: 172.30.0.253

200 860254102

|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:SIGNIFICANT><:2000>

01/06/2009 17:38:37.890 CCM|MGCPTrunkD - Sending the prefix digits and or Attendant Number for Device=AALN/S0/SU0/0@uk-srst.mycompany.local, CombinedDigits=5750|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:STATE transition=""><:2000>

01/06/2009 17:38:37.890 CCM|SMDMSharedData::findSubscriptionIdExistsInSubscribeeState - SubscriptionId=2|0|60 found|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:DETAILED><:FFFFFF>

01/06/2009 17:38:37.890 CCM|SMDMSharedData::updateSubscribeeStateAndNotify - updated state entry for outSubId = 2|0|60, NotifyMsg = SNFNotifyMsg: state = 0, reason = 0, retryAfter = -1, subscriptionType = BUSY_AVAILABLE_IDLE , content = SNFLegacyContent with content data set to: busy, cepn = 1b9de5a5-d1f9-a9bb-9c78-b3d8425e9817, mSubscribeePid = (0,0,0)

, and sent notify to subscribers|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:DETAILED><:FFFFFF>

01/06/2009 17:38:37.892 CCM|SMDMSharedData::findAliasRegInfo - AliasName = b0bfdf8e-e4a7-88c7-e3cc-f405a26c7bed not in AliasInfo hashmap|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:DETAILED><:FFFFFF>

01/06/2009 17:38:37.892 CCM|DeviceManager::star_DmPidReq - RequestedName=b0bfdf8e-e4a7-88c7-e3cc-f405a26c7bed LookupName=b0bfdf8e-e4a7-88c7-e3cc-f405a26c7bed|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:DETAILED><:FFFFFF>

01/06/2009 17:38:37.892 CCM|SMDMSharedData::findLocalDevice - Name=5750:mycompany-Pt Key=b0bfdf8e-e4a7-88c7-e3cc-f405a26c7bed isActvie=1 Pid=(2,148,171) found|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:DETAILED><:FFFFFF>

01/06/2009 17:38:37.892 CCM|Digit analysis: wait_DmPidRes - Name=[b0bfdf8e-e4a7-88c7-e3cc-f405a26c7bed] cmDeviceType=[UserDevice] Pid=LineControl(2,100,148,171)|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:ARBITRARY><:FFFFFF>

01/06/2009 17:38:37.893 CCM|MGCPHandler send msg SUCCESSFULLY to: 172.30.0.253

CRCX 8883 AALN/S0/SU0/0@uk-srst.mycompany.local MGCP 0.1

C: A000000002896347000000F5

X: 0

L: p:20, a:PCMU, s:off, t:00

M: recvonly

R: L/hu

Q: process,loop

|<:STANDALONECLUSTER><:10.1.9.6><:2><:172.30.0.253><:AALN>SU0@uk-srst.mycompany.loc><:SIGNIFICANT><:2000>

01/06/2009 17:38:38.065 CCM|MGCPHandler received msg from: 172.30.0.253

200 8883 OK

I: 34

v=0

c=IN IP4 172.30.0.253

m=audio 16392 RTP/AVP 0 100

a=rtpmap:100 X-NSE/8000

a=fmtp:100 192-194,200-202

a=X-sqn:0

a=X-cap: 1 audio RTP/AVP 100

a=X-cpar: a=rtpmap:100 X-NSE/8000

a=X-cpar: a=fmtp:100 192-194,200-202

a=X-cap: 2 image udptl t38

Nicholas Matthews · ‎01-07-2009

I would try putting this on your fxo voice port:

no battery-reversal

hth,

nick

oldcreek12 · ‎01-07-2009

Thanks a lot nick, but it did not help, I looked at MGCP debug again, and found this message sent by C2801 suspicious:

*Jan 6 16:31:47.130: MGCP Packet sent to 10.1.9.6:2427--->

NTFY 860251789 aaln/S0/SU0/0@uk-srst MGCP 0.1

N: ca@10.1.9.6:2427

X: 0

O: L/hu

<---

So somehow C2801 is sending on-hook event to CUCM although calling party never hung up during the call.

I tested the setup in US before it is shipped to UK, could there be any interop issue between C2801 FXO ports and UK local phone switch?

Nicholas Matthews · ‎01-07-2009

It's hard to say without getting into the CCAPI debugs and FXO port debugs. It's possible you're getting some type of analog signaling causing a problem from the provider. Sometimes we see this with battery-reversal, but apparently that is not it here.

hth,

nick

oldcreek12 · ‎01-08-2009

Hi, Nick,

I attached CCAPI debug output on C2801, how do I turn on FXO debug? Thanks a lot for your time.

Nicholas Matthews · ‎01-08-2009

From this debug, all it really shows it that the router is getting another call incoming on the FXO port. It sees a normal call disconnect from the previous leg, and sees a whole new call come in.

Sometimes we can see this for hookflash situations, and maybe the timers are off.

hth,

nick

oldcreek12 · ‎01-08-2009

Hi, Nick,

I tried different hookflash timers, still can not complete inbound call. I collected vpm signal debug, not sure it helps or not.

The debug output is for groundstart, I tried loopstart also.

Nicholas Matthews · ‎01-08-2009

We're definitely receiving signals from the provider. You may want to check the SIG_0110 and SIG_0100 (ABCD) bits against this document:

http://www.cisco.com/en/US/tech/tk652/tk653/technologies_tech_note09186a00800a6210.shtml#Topic3

hth,

nick

oldcreek12 · ‎01-08-2009

Hi, Nick,

But the MGCP debug shows that it is FXO port sends on-hook event first to CA before previous call is completed, and caller from PSTN side never hangs up, how can FXO sees a complete new call?

Jian

Nicholas Matthews · ‎01-08-2009

There's something going on with the ABCD bit toggling with the provider. Some of the bits are toggled during ringing that appear to be interpreted as offhook/onhook rather than ringing.

Without spending more time analyzing all of the individual bits and the FXO/FXS signaling, it's hard to say.

hth,

nick

oldcreek12 · ‎01-08-2009

I will ask our UK local admin to contact phone company, and at the same time I will ship an US CO simulator over, this should completely isolate the problem.

Once again, thank you for your help, nick. I will definitely update you.