Buy or Renew
Buy or Renew
Cisco + Splunk: It’s a new day for your data. Learn more.
 
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
6695
Views
13
Helpful
28
Replies

Intermittent calls dropping, returning fast busy

Rick Morris
Level 6
Level 6

‎10-29-2010 10:59 AM - edited ‎03-16-2019 01:38 AM

I am working an issue for Intermittent calls dropping, returning fast busy.

Here is the output of the RTMT log for the issue we see.

10/28/2010 15:37:51.546 CCM|Digit analysis: match(pi="2", fqcn="5133866428", cn="6428",plv="5", pss="BlockExploitPSTN_PT:BlockNothing:Phones_PT:System_PT:HQPSTN_PT",

TodFilteredPss="BlockExploitPSTN_PT:BlockNothing:Phones_PT:System_PT:HQPSTN_

PT",

dd="913606645773",dac="0")|<CLID::StandAloneCluster><NID::192.168.26.3><CT::

2,100,39,1.25832353><IP::192.168.26.56><DEV::SEP0016478B0C8D><LVL::State

Transition><MASK::0800>

10/28/2010 15:37:51.546 CCM|Digit analysis: analysis

results|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,39,1.2583

results|2353

><IP::192.168.26.56><DEV::SEP0016478B0C8D><LVL::State

Transition><MASK::0800>

10/28/2010 15:37:51.546 CCM||PretransformCallingPartyNumber=6428

|CallingPartyNumber=513

|DialingPartition=HQPSTN_PT

|DialingPattern=9.1[2-9]XX[2-9]XXXXXX

|FullyQualifiedCalledPartyNumber=913606645773

10/28/2010 15:37:52.014 CCM|StationD: (0000034) SEP0016478B0C8D ,

star_MediaExchangeAgenaOpenLogicalChannel packetSize=20, codec=4,

ci=40794829|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,16,129626

.2><IP::192.168.26.254><DEV::Port 26285><LVL::Detailed><MASK::0020>

10/28/2010 15:37:52.014 CCM|StationD: (0000034)

StopTone.|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,16,129626.2

><IP::192.168.26.254><DEV::Port 26285><LVL::State

>Transition><MASK::0020>

10/28/2010 15:37:52.014 CCM|StationD::star_StationOutputOpenReceiveChannel

myCi=40794829

keylen=0|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,16,129626.2>

<IP::192.168.26.254><DEV::Port 26285><LVL::Detailed><MASK::0800>

10/28/2010 15:37:52.014 CCM|StationD: (0000034) OpenReceiveChannel

conferenceID=40794829 passThruPartyID=34135337 millisecondPacketSize=20

compressionType=4(Media_Payload_G711Ulaw64k) RFC2833PayloadType=0 qualifierIn=? sourceIpAddr=IpAddr.type:0 ipAddr:0xc0a81a02000000000000000000000000(192.168.26.2). myIP: IpAddr.type:0

ipv4Addr:0xc0a81a38(192.168.26.56)

|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,16,129626.2><IP:

|:192

.168.26.254><DEV::Port 26285><LVL::Significant><MASK::0020>

10/28/2010 15:38:33.996 CCM|TranslateAndTransport(129626)::wait_SdlCloseInd

- ERROR: H245 signaling connection aborted!!!|

117380916| 2010/10/28 15:38:33.996| 002| SdlSig | TtFailure

| h245CloseSessionRequest_wait_for_LcseReleaseConfirm|

H245SessionManager(2,100,23,129626)| TranslateAndTransport(2,100,16,129626)|

(2,100,39,1).25832393-(SEP0016478B0C8D:192.168.26.56)| [R:NP - HP: 0, NP: 0,

LP: 0, VLP: 0, LZP: 0 DBP: 0]

10/28/2010 15:38:33.998 CCM|StationD: (0000034)

StopTone.|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,39,1.258323

93><IP::192.168.26.56><DEV::SEP0016478B0C8D><LVL::State

Transition><MASK::0020>

10/28/2010 15:38:33.998 CCM|StationD: (0000034) StartTone

tone=37(ReorderTone),

direction=0.|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,39,1.258

32393><IP::192.168.26.56><DEV::SEP0016478B0C8D><LVL::State

Transition><MASK::0020>

10/28/2010 15:38:33.999 CCM|StationD: (0000034) SelectSoftKeys instance=1

reference=40794829 softKeySetIndex=8

validKeyMask=fffffffb.|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,10

0,39,1.25832393><IP::192.168.26.56><DEV::SEP0016478B0C8D><LVL::State

Transition><MASK::0020>

10/28/2010 15:38:33.999 CCM|StationD: (0000034) DEBUG-

star_DSetCallState(11) State of cdpc(265108) is

6.|<CLID::StandAloneCluster><NID::192.168.26.3><CT::2,100,39,1.25832393><IP:

:192.168.26.56><DEV::SEP0016478B0C8D><LVL::Detailed><MASK::0020>

You should investigate why the TCP session between the server and the gateway closed, and identify the failure on the network devices between them.

It took me some time to find out this because your CUCM version is not very specific with the messages from the logs, look at this bug to enhance the trace files

CSCsm26355

Symptom:

delayed or failed h323 call setup

Conditions:

CM sends TCP SYN to remote peer for h245 session but does not receive any response.

Workaround:

None.

Further Problem Description:

This is a request for additional debugging to make it clear when h.245 TCP session setup fails.

There are currently no intuitive SDI or alarm messages to indicate this failure. It usually requires SDL traces to identify failure to setup the TCP session.

After upgrade to fixed version the following errors appear in the CM SDI

traces:

h.245 tcp session setup failure:

TCP ERROR: H245ListenReq or H245ConnectReq failure, or received SdlCloseInd from H245Handler, Perform cleanup of H245 Session

established h.245 session experiences TCP keepalive timeout:

TranslateAndTransport(%d)::wait_SdlCloseInd - ERROR: H245 signaling connection aborted

established h.245 session receives unexpected TCP FIN or RST:

TranslateAndTransport(%d)::wait_SdlCloseInd - ERROR: H245 signaling connection aborted

My issue is where to look.

Here is the Topology:

CUCM 7.1 --- 2960 (Pub G0/18 Sub G0/15) --- Core 3750 (G2/0/1) --- Gateway 2851

I verified on all interfaces that there are no errors.  Nothing in the logs to indicate any issues.

Any direction will be appreciated and will receive a rating.

Thanks,

Rick

Labels:
0 Helpful
28 Replies 28

asandborgh
Level 4
Level 4

‎10-29-2010 11:09 AM

Hi Rick,

It would be interesting to see a debug h245 asn1 and a debug h225 asn1 from the gateway to see it's reaction.

HTH,

Art

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 11:29 AM

Thanks.  I have the debugs running now and waiting for the call drop to happen again to review the logs.  I am not familair with these debugs, what should I be looking for?

0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 11:48 AM

H245 and H225 are protocols that work in the H.323 suite for call set

up and media.  They have disconnect cause codes similiar to Q.931 that sometimes will give you clues.

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 12:15 PM

Here is one of the calls that dropped.  I filtered to find the number called, my issue from here is how do I find the termination of this call in the logs from this info:

/4103266731
filtering...
            dialedDigits : "14103266731"
          }
          activeMC FALSE
          conferenceID '00CCC5F66113B1CCF51D7D02C0A81A87'H
          conferenceGoal create : NULL
          callType pointToPoint : NULL
          sourceCallSignalAddress ipAddress :
          {
            ip 'C0A81A03'H
            port 1720
          }
          callIdentifier
          {
            guid '00CCC5F66113B1CCF51D7D02C0A81A87'H
          }
          mediaWaitForConnect FALSE
          canOverlapSend FALSE
          multipleCalls FALSE
          maintainConnection FALSE
        }
        h245Tunneling FALSE
        nonStandardControl
        {

          {
            nonStandardIdentifier h221NonStandard :
            {
              t35CountryCode 181
              t35Extension 0
              manufacturerCode 18
            }
            data '81E40020040001030003000103'H
          }
        }
      }
    }

119207: Oct 29 14:33:05.214 EDT: H225 NONSTD INCOMING ENCODE BUFFER::= 81E400200
40001030003000103

0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 12:24 PM

Rick,

One of the difficulties with the two debugs is the format that they produce (as you have already experienced).  But there is very good information in there.  If you could post the section of the file just before where you found the number and then probably 200 lines below I may be able to dig something out for you.

Thanks,

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 01:03 PM

I have attached the debug output in a txt file.

74421-debug-output.txt.zip
0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 01:19 PM

Well,  we were getting somewhere, they were still in negotiation, but we had not arrived at actual media channel setup or the failure, can you give  me more?

Thanks again,

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 01:21 PM

hers is more

74423-debug-output.txt.zip
0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 01:36 PM

OK, What I am seeing is that the unit does open a logical channel and it

looks like #32002 (or something close - is this true?) is dialed and at that point the gateway suddenly sends a "release complete" (search on release in the debug).   This indicates to me that there is something going on at the voice port or beyond.  Can you do a debug vpm signal and post the file?

Thanks again,

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 02:07 PM

I am going to get the debugs you mentioned, does this go back in time or will I need to run the debug, wait for the issue to happen, then search for the issue in the log?

0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 02:36 PM

Hi Rick,

Unfortunately we need to have it happen again to capture the event.  Additionally please send the capture of a good call along with the details on a failed one - comparison gives us more information on your actual environemnt.  Can you also tell me what dial strings you are sending out (both successful and failed)?  Is this standard NANP, another standard E.164 country out dila, or something non-standard?

Thanks,

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎10-29-2010 02:59 PM

i will follow up on monday.  the ckt is pri i believe but will know more then.

thank you so much for your assistance.  i appreciate it a lot

0 Helpful

asandborgh
Level 4
Level 4
In response to Rick Morris

‎10-29-2010 02:42 PM

Rick,

One other thing I should have asked much earlier (thought I had) - what kind of PSTN trunk is this going out?  If it is a PRI please run a debug isdn q931 rather than the vpm.

Art

0 Helpful

Rick Morris
Level 6
Level 6
In response to asandborgh

‎11-03-2010 08:43 AM

I rebooted the router Saturday night and had no report of issues until today.  The problem has resurfaced.

I have applied the debug vpm signal command and will post the results when the issue happens again.  I am looking at the log and see nothing posted outside of anything different from what was already in the log.  Should I see something different?

002912: Nov  3 11:41:38.718 EDT: %ISDN-6-DISCONNECT: Interface Serial0/1/0:2  di
sconnected from unknown , call lasted 193 seconds
002913: Nov  3 11:41:48.538 EDT: %ISDN-6-DISCONNECT: Interface Serial0/1/0:1  di
sconnected from 614xxx5000 , call lasted 81 seconds
002914: Nov  3 11:41:56.650 EDT: %ISDN-6-DISCONNECT: Interface Serial0/1/0:0  di
sconnected from 586xxx0434 , call lasted 193 seconds
002915: Nov  3 11:42:12.890 EDT: %ISDN-6-CONNECT: Interface Serial0/1/0:0 is now
connected to 818xxx7229 N/A
002916: Nov  3 11:42:19.042 EDT: %ISDN-6-DISCONNECT: Interface Serial0/1/0:0  di
sconnected from 818xxx7229 , call lasted 6 seconds
TF-CORP-VOIPGW-1#sh debug

Voice Port Module signaling debugging is on

TF-CORP-VOIPGW-1#

0 Helpful
Getting Started

Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community:

Customers Also Viewed These Support Documents