[cisco-voip] Weird ISDN disconnection issue when using H323 and CUCM 8.0.2C

Tue Jul 27 18:05:49 EDT 2010

the non standard TCS messae is most often en when the TCS you receive
contains every capabiltiy in the universe due to your call using
dial-peer 0 as it goes throgh the gateway. this theory also explains
why you only have the issue in one direction. take one of the voip
dial pers you have being used for calls from the PSTN to the CUCM, and
put
incoming called-number .
...on it. my hyphen might be misplaced, but that will probably fix your issue.

-Peter

On Tue, Jul 27, 2010 at 11:27 AM, Ki Wi <kiwi.voice at gmail.com> wrote:
> 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.
>
> _______________________________________________
> cisco-voip mailing list
> cisco-voip at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-voip
>
>