[cisco-voip] Weird ISDN disconnection issue when using H323 and CUCM 8.0.2C
Ki Wi
kiwi.voice at gmail.com
Tue Jul 27 11:27:20 EDT 2010
At the CCM trace, i noticed the following
23:02:13.487 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
numberSetup=1 numberMember=0
vmEnabled=0|1,100,49,1.1475986^10.0.12.125^SEP0019DXXXXXXX
23:02:13.487 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
RouteListCdrc::create CI = 18217036 BRANCH = 0
mIsEmccHunt=0|1,100,49,1.1475986^10.0.12.125^SEP0019DXXXXXXX
23:02:14.860 |ConnectionManager - wait_AuDisconnectRequest ERROR:NO ENTRY
FOUND IN
TABLE,CI(18217035,18217036),dcType=1,IFCreated(0,0),PID(0-0,0-0),IFHandling(0,0),MCNode(0,0)|1,100,49,1.1475986^10.0.13.5^SEP0019DXXXXXXX
23:02:14.860 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2
videocapable=0|1,100,49,1.1475986^10.0.13.5^SEP0019DXXXXXXX
23:02:16.066 |LineControl TEST DEBUGS: Number of entries in CallTable is =
1
|1,100,49,1.1475989^10.0.12.125^SEP0019DXXXXXXX
*23:02:17.768 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,49,1.1475991^10.0.12.125^SEP0019DXXXXXXX
23:02:17.768 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,49,1.1475991^10.0.12.125^SEP0019DXXXXXXX
23:02:17.768 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,49,1.1475991^10.0.12.125^SEP0019DXXXXXXX
23:02:17.769 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,49,1.1475991^10.0.12.125^SEP0019DXXXXXXX
23:02:17.769 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,49,1.1475991^10.0.12.125^SEP0019DXXXXXXX*
23:02:19.316 |LineControl TEST DEBUGS: Number of entries in CallTable is =
1
|1,100,49,1.1475997^10.0.12.125^SEP0019DXXXXXXX
23:02:19.317 |MediaManager(3037)::wait_AuDisconnectRequest,
mCleanupPreallocatedMTP=0|1,100,49,1.1475997^10.0.12.125^SEP0019DXXXXXXX
23:02:19.335 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2 videocapable=0|1,100,16,2355.22^10.0.13.5^Port 62671
23:02:19.335 |ViprUtils: Number has no +, not a valid E164
[99XXXXXX9]|1,100,16,2355.22^10.0.13.5^Port 62671
23:02:21.005 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
numberSetup=0 numberMember=0
vmEnabled=0|1,100,49,1.1476001^10.0.12.125^SEP0019DXXXXXXX
23:02:21.005 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
RouteListCdrc::create CI = 18217038 BRANCH = 0
mIsEmccHunt=0|1,100,49,1.1476001^10.0.12.125^SEP0019DXXXXXXX
23:02:22.227 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4201.1^*^*
23:02:22.227 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4201.1^*^*
23:02:22.227 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4201.1^*^*
23:02:22.227 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4201.1^*^*
23:02:22.227 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4201.1^*^*
23:02:26.238 |TranslateAndTransport(2359)::wait_SdlCloseInd - ERROR: H245
signaling connection aborted!!!|1,100,16,2359.7^10.0.13.5^Port 65014
23:02:26.238 |H225Cdpc(0003107)::call_received7_TcpStopSessionInd: H225 Tcp
session terminated abnormally|1,100,49,1.1476001^10.0.12.125^SEP0019DXXXXXXX
23:02:26.239 |MediaManager(3038)::wait_AuDisconnectRequest,
mCleanupPreallocatedMTP=0|1,100,49,1.1476001^10.0.12.125^SEP0019DXXXXXXX
23:02:26.240 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2
videocapable=0|1,100,49,1.1476001^10.0.12.125^SEP0019DXXXXXXX
23:02:29.374 |LineControl TEST DEBUGS: Number of entries in CallTable is =
1
|1,100,49,1.1476014^10.0.12.125^SEP0019DXXXXXXX
23:02:30.317 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
numberSetup=0 numberMember=0
vmEnabled=0|1,100,49,1.1476015^10.0.12.125^SEP0019DXXXXXXX
23:02:30.317 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
RouteListCdrc::create CI = 18217040 BRANCH = 0
mIsEmccHunt=0|1,100,49,1.1476015^10.0.12.125^SEP0019DXXXXXXX
23:02:31.624 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4202.1^*^*
23:02:31.624 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4202.1^*^*
23:02:31.624 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4202.1^*^*
23:02:31.624 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4202.1^*^*
23:02:31.624 |H245Handler(1)::There is an error in decoding H.245 TCS
Non-Standard data.|1,100,211,4202.1^*^*
23:02:39.148 |MediaManager(3039)::wait_AuDisconnectRequest,
mCleanupPreallocatedMTP=0|1,100,49,1.1476031^10.0.12.125^SEP0019DXXXXXXX
23:02:39.158 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2 videocapable=0|1,100,16,2360.11^10.0.13.5^Port 11939
23:02:39.158 |MediaResourceManager::sendAllocationResourceErr - ERROR - no
MOH device configured|1,100,16,2360.11^10.0.13.5^Port 11939
23:02:40.126 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
numberSetup=1 numberMember=0
vmEnabled=0|1,100,49,1.1476036^10.0.12.125^SEP0019DXXXXXXX
23:02:40.126 |RouteListControl::idle_CcSetupReq - RouteList(RL_SG),
RouteListCdrc::create CI = 18217043 BRANCH = 0
mIsEmccHunt=0|1,100,49,1.1476036^10.0.12.125^SEP0019DXXXXXXX
23:02:45.090 |H225Cdpc(0003109)::call_received7_TcpStopSessionInd: H225 Tcp
session terminated abnormally|1,100,49,1.1476036^10.0.12.125^SEP0019DXXXXXXX
23:02:45.090 |TranslateAndTransport(2361)::wait_SdlCloseInd - ERROR: H245
signaling connection aborted!!!|1,100,16,2361.7^10.0.13.5^Port 18637
23:02:45.091 |MediaManager(3040)::wait_AuDisconnectRequest,
mCleanupPreallocatedMTP=0|1,100,49,1.1476036^10.0.12.125^SEP0019DXXXXXXX
23:02:45.092 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2
videocapable=0|1,100,49,1.1476036^10.0.12.125^SEP0019DXXXXXXX
23:02:46.500 |LineControl TEST DEBUGS: Number of entries in CallTable is =
1
|1,100,49,1.1476043^10.0.12.125^SEP0019DXXXXXXX
23:04:16.908 |ViprUtils: Number has no +, not a valid E164
[99XXXXXX9]|1,100,16,2360.11^10.0.13.5^Port 11939
23:04:16.909 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1
videoCapable=0, party 2 videocapable=0|1,100,16,2360.11^10.0.13.5^Port 11939
23:04:16.910 |LineControl TEST DEBUGS: Number of entries in CallTable is =
0
This is the first time I met such error.
Over at debug h245 asn1 and h225 asn1
ul 27 12:42:32.905: H225.0 OUTGOING ENCODE BUFFER::=
280032C0060008914A00042800B500001240013C050100000A00180A2AF90080B8DF6E3ED4E1C4070090010A000C7D05800100010010A801003A0140B50000123360010100011E2C1E0284841C269E8100036774640000001B4350472C0D0A50524E2C6973646E2A2C2C4E4554352A2C0D0A0D0A224204677464011B4350472C0D0A50524E2C6973646E2A2C2C4E4554352A2C0D0A0D0A
Jul 27 12:42:32.905:
Jul 27 12:42:32.921: //19868/80B8DF6E0700/CCAPI/cc_api_call_alert:
Interface=0x14641E2C, Progress Indication=NULL(0), Signal Indication=NOT
PRESENT(255)
Jul 27 12:42:32.921: //19868/80B8DF6E0700/CCAPI/cc_api_call_alert:
Call Entry(Retry Count=0, Responsed=TRUE)
Jul 27 12:42:32.921: //19867/80B8DF6E0700/CCAPI/ccCallAlert:
Progress Indication=INBAND(8), Signal Indication=NOT PRESENT(255)
Jul 27 12:42:32.921: //19867/80B8DF6E0700/CCAPI/ccCallAlert:
Call Entry(Responsed=TRUE, Alert Sent=TRUE)
Jul 27 12:42:32.921:
//19868/80B8DF6E0700/CCAPI/cc_api_get_called_ccm_detected:
CallInfo(ccm detected=0)
Jul 27 12:42:32.921: //19867/80B8DF6E0700/CCAPI/cc_api_get_delay_xport:
CallInfo(delay xport=FALSE)
Jul 27 12:42:36.377: H225 NONSTD OUTGOING PDU ::=
value H323_UU_NonStdInfo ::=
{
version 1
protoParam qsigNonStdInfo :
{
iei 28
rawMesg '1C269E8100036774640000001B41434D2C0D0A50...'H
}
progIndParam progIndIEinfo :
{
progIndIE '00000008'H
}
}
Jul 27 12:42:36.377: H225 NONSTD OUTGOING ENCODE BUFFER::=
E0010100011C281C269E8100036774640000001B41434D2C0D0A50524E2C6973646E2A2C2C4E4554352A2C0D0A0D0A18800006000400000008
Jul 27 12:42:36.377:
Jul 27 12:42:36.377: H225.0 OUTGOING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body releaseComplete :
On Tue, Jul 27, 2010 at 6:38 PM, Jason Aarons (US) <
jason.aarons at us.didata.com> wrote:
> Your transmitting the disconnect to telco, problem is higher up the stack.
> Debug voip ccapi inout, debug h225 asn, etc, pull a CCM Trace and use Triple
> Combo Tool.
>
>
>
> I’d consider switching from H323 to SIP, traces are much easier to read.
>
>
>
> I tend to suspect your requiring a MTP resource for some reason which isn’t
> available, or could be in H245 codec failure, or your having a rtp audio
> stream problem, etc.
>
>
>
> *From:* cisco-voip-bounces at puck.nether.net [mailto:
> cisco-voip-bounces at puck.nether.net] *On Behalf Of *Ki Wi
> *Sent:* Tuesday, July 27, 2010 12:36 AM
> *To:* Cisco VoIP List
> *Subject:* [cisco-voip] Weird ISDN disconnection issue when using H323 and
> CUCM 8.0.2C
>
>
>
> The setup is based on cucm 8.0.2c & 2 x vg (at 2 different site) using
> h.323
>
> 1 vg is based on 15.0(1)M1
> 1 vg is based on 15.1(2)T
>
> Both of them display the same characteristic when doing outbound call to
> PSTN while inbound call is not affected by this issue.
>
> When 1 x isdn channel is used(taken) up, others cannot make outbound call
> at all.
>
> When in SRST mode, both vg with their individual ISDN connection can
> receive inbound and outbound call from PSTN normally.
>
> Currently my interim solution is to allow all the phones to stay in SRST
> while trying to find out the root cause.
> I'm able to replicate the problem by allowing my CIPC to connect to the
> callmanager and make 2 x outgoing call to my mobile. First one will go
> through while second call will get disconnected for some unknown reason. I
> noticed about this temporary failure issue but what bug me is nothing goes
> wrong when so many phones are in SRST mode right now.
>
> I have attached the debug isdn q931 configuration.
>
> Jul 27 04:20:00.271: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type
> 0x12 is 0x0 0x0, Calling num 62XXXX50
> Jul 27 04:20:00.271: ISDN Se0/0/0:15 Q931: Sending SETUP callref = 0x0C32
> callID = 0x8BB3 switch = primary-net5 interface = User
> Jul 27 04:20:00.271: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8 callref =
> 0x0C32
> Bearer Capability i = 0x8090A3
> Standard = CCITT
> Transfer Capability = Speech
> Transfer Mode = Circuit
> Transfer Rate = 64 kbit/s
> Channel ID i = 0xA9839E
> Exclusive, Channel 30
> Progress Ind i = 0x8183 - Origination address is non-ISDN
> Calling Party Number i = 0x0081, '62XXXX50'
> Plan:Unknown, Type:Unknown
> Called Party Number i = 0x80, '9XXXXXX9'
> Plan:Unknown, Type:Unknown
> Jul 27 04:20:00.599: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8 callref
> = 0x8C32
> Channel ID i = 0xA9839E
> Exclusive, Channel 30
> Jul 27 04:20:02.079: ISDN Se0/0/0:15 Q931: RX <- PROGRESS pd = 8 callref =
> 0x8C32
> Progress Ind i = 0x8482 - Destination address is non-ISDN
> Progress Ind i = 0x8488 - In-band info or appropriate now available
>
> Jul 27 04:20:04.051: ISDN Se0/0/0:15 Q931: RX <- PROGRESS pd = 8 callref =
> 0x8C32
> Progress Ind i = 0x8484 - Call has returned to the ISDN
> Jul 27 04:20:04.139: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref =
> 0x8C32
> Jul 27 04:20:05.419: ISDN Se0/0/0:15 Q931: RX <- CONNECT pd = 8 callref =
> 0x8C32
> Date/Time i = 0x0A071B0C14
> Date (dd-mm-yr) = 10-07-27
> Time (hr:mnt:sec) = 12:20:24
> Jul 27 04:20:05.423: %ISDN-6-CONNECT: Interface Serial0/0/0:29 is now
> connected to 9XXXXXX9 N/A
> Jul 27 04:20:05.423: ISDN Se0/0/0:15 Q931: TX -> CONNECT_ACK pd = 8
> callref = 0x0C32
> Jul 27 04:20:16.959: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type
> 0x12 is 0x0 0x0, Calling num 62XXXX50
> Jul 27 04:20:16.959: ISDN Se0/0/0:15 Q931: Sending SETUP callref = 0x0C33
> callID = 0x8BB4 switch = primary-net5 interface = User
> Jul 27 04:20:16.959: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8 callref =
> 0x0C33
> Bearer Capability i = 0x8090A3
> Standard = CCITT
> Transfer Capability = Speech
> Transfer Mode = Circuit
> Transfer Rate = 64 kbit/s
> Channel ID i = 0xA9839D
> Exclusive, Channel 29
> Progress Ind i = 0x8183 - Origination address is non-ISDN
> Calling Party Number i = 0x0081, '62XXXX50'
> Plan:Unknown, Type:Unknown
> Called Party Number i = 0x80, '9XXXXXX9'
> Plan:Unknown, Type:Unknown
> Jul 27 04:20:17.287: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8 callref
> = 0x8C33
> Channel ID i = 0xA9839D
> Exclusive, Channel 29
> Jul 27 04:20:18.779: ISDN Se0/0/0:15 Q931: RX <- PROGRESS pd = 8 callref =
> 0x8C33
> Progress Ind i = 0x8482 - Destination address is non-ISDN
> Progress Ind i = 0x8488 - In-band info or appropriate now available
>
> Jul 27 04:20:19.039: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref =
> 0x8C33
> Progress Ind i = 0x8484 - Call has returned to the ISDN
> Jul 27 04:20:22.791: ISDN Se0/0/0:15 Q931: TX -> DISCONNECT pd = 8 callref
> = 0x0C33
> Cause i = 0x80A9 - Temporary failure
> Jul 27 04:20:22.927: ISDN Se0/0/0:15 Q931: RX <- RELEASE pd = 8 callref =
> 0x8C33
>
>
>
>
> ------------------------------
>
> * Disclaimer: This e-mail communication and any attachments may contain
> confidential and privileged information and is for use by the designated
> addressee(s) named above only. If you are not the intended addressee, you
> are hereby notified that you have received this communication in error and
> that any use or reproduction of this email or its contents is strictly
> prohibited and may be unlawful. If you have received this communication in
> error, please notify us immediately by replying to this message and deleting
> it from your computer. Thank you. *
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20100727/7ed332b1/attachment.html>
More information about the cisco-voip
mailing list