[cisco-voip] h323 to call manager inbound calls randomly complete

Thu Mar 18 14:33:20 EDT 2010

Scott Irey
Network & Telecom Systems Engineer
Oakland University
Office: 248.370.2808
Mobile: 248.505.9827

-----Original Message-----
From: Scott Irey [mailto:irey at oakland.edu]
Sent: Thursday, March 18, 2010 1:54 PM
To: 'Peter Slow'
Cc: 'Nick Matthews'; 'cisco-voip at puck.nether.net'
Subject: RE: [cisco-voip] h323 to call manager inbound calls randomly
complete

Hi Thanks for the input. Here is a copy of the tcp debug as well as cch323
h225 debug for a call that did not complete. Seems to be about every other
call that does not complete. There is an FWSM module on one of the cores
that thing transverses. Right now it is permit IP between the two subnets
for testing purposes.

Mar 15 15:30:06.594: TCB492D19A0 created
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_NO_DELAY (0)
483CCCEC
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_TOS (11) 483CCD34
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_NONBLOCKING_WRITE
(10) 483CCD78
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_NONBLOCKING_READ
(14) 483CCD78
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP keepalive timeout
(17) 483CCD78
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_VRFTABLEID (20)
48F1C694
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_NO_DELAY (0)
483CCD34
Mar 15 15:30:06.594: TCB492D19A0 setting property TCP_ALWAYSPUSH (15)
483CCD34
Mar 15 15:30:06.594: TCP: Random local port generated 61648, network 1
Mar 15 15:30:06.594: TCB492D19A0 bound to x.x.x.x.61648
Mar 15 15:30:06.594: Reserved port 61648 in Transport Port Agent for TCP
IP type 1
Mar 15 15:30:06.594: TCP: sending SYN, seq 3252130252, ack 0
Mar 15 15:30:06.594: TCP0: Connection to x.x.x.x:1720, advertising MSS 536
Mar 15 15:30:06.594: TCP0: state was CLOSED -> SYNSENT [61648 ->
x.x.x.x(1720)]
Mar 15 15:30:06.594: //628287/FED119DB8D03/H323/cch323_h225_set_new_state:
Changing from H225_IDLE state to H225_IDLE state
Mar 15 15:30:06.598: TCP0: state was SYNSENT -> ESTAB [61648 ->
x.x.x.x(1720)]
Mar 15 15:30:06.598: TCP: tcb 492D19A0 connection to x.x.x.x:1720, peer
MSS 1380, MSS is 536
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/run_h225_sm: Received
event H225_EV_SETUP while at state H225_IDLE
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/check_qos_and_send_setup:
Setup ccb 0x4961850C
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/run_h225_sm: Received
event H225_EV_FS_SETUP while at state H225_IDLE
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/idle_fsSetup_hdlr: Setup
ccb 0x4961850C
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/copy_token_from_ccb:
copy_token_from_ccb: Entered
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/generic_send_setup:
generic_send_setup: is_overlap = 0, info_complete = 0
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/generic_send_setup:
sending calling IE
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/generic_send_setup: ======
PI = 0
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/generic_send_setup: Send
infoXCap=128, infoXRate=16, rateMult=0, xMode=128, info_layer1_prot=163
Mar 15 15:30:06.598: //628287/FED119DB8D03/H323/generic_send_setup: src
address = x.x.x1.255; dest address = x.x.x.10
Mar 15 15:30:06.602: //628287/FED119DB8D03/H323/cch323_h225_set_new_state:
Changing from H225_IDLE state to H225_REQ_FS_SETUP state
Mar 15 15:30:08.442: x.x.x1.255:61648 <---> x.x.x.10:1720   congestion
window changes
Mar 15 15:30:08.442: cwnd from 536 to 536, ssthresh from 65535 to 1072
Mar 15 15:30:08.442: TCP0: timeout #1 - timeout is 3674 ms, seq 3252130253
Mar 15 15:30:08.442: TCP: (61648) -> x.x.x.10(1720)
Mar 15 15:30:12.118: TCP0: timeout #2 - timeout is 7348 ms, seq 3252130253
Mar 15 15:30:12.118: TCP: (61648) -> x.x.x.10(1720)

Mar 15 15:30:16.682: //628287/FED119DB8D03/H323/run_h225_sm: Received
event H225_24
Mar 15 15:30:16.682: //628287/FED119DB8D03/H323/cch323_h225_send_release:
h225TerminateRequest: src address = -1915609089; dest address = x.x.x.10
Mar 15 15:30:16.682: //628287/FED119DB8D03/H323/cch323_h225_set_new_state:
Changing from H225_REQ_FS_SETUP state to H225_IDLE state

Scott Irey
Network & Telecom Systems Engineer
Oakland University
Office: 248.370.2808
Mobile: 248.505.9827

-----Original Message-----
From: Peter Slow [mailto:peter.slow at gmail.com]
Sent: Tuesday, March 16, 2010 8:22 PM
To: Scott Irey
Cc: Nick Matthews; cisco-voip at puck.nether.net
Subject: Re: [cisco-voip] h323 to call manager inbound calls randomly
complete

Scott,
   debug ip tcp transact is the right thing to be looking at... Can we
see? Also, can you describe the network in between the gateway and the
CUCM server? what devices are in between and what does the network
look like?

   How many CUCM servers are in the cluster? Ideally, a timeout with
one or two would lead to a new TCP session being attempted with a
different callmanager server. if there are multiple callmanagers
involved and you see the same thing for that call  with the TCP
session establishment to multiple servers, that tells us one thing
(network) if it continually fails with one server but works with
another (and the two servers are in the same location) that might be
pointing at that particular CUCM. Either way, while we are figuring
out what the problem is, invlving multiple servers should help reduce
the actual impact of the issue. Use multiple dial-peers combined with
an h323 voice class and "h225 timeout tcp establish" to knock the
timers down to something that allows for quick failover to the next
dialpeer when the TCP session doesn't start up in a timely fashion.

-Pete

On Tue, Mar 16, 2010 at 1:55 PM, Scott Irey <irey at oakland.edu> wrote:
> Thanks! Funny you mentioned that as I did turn on debug ip tcp
> transactions and am able to see some tcp timeouts. Haven't had much time
> to go any further (not a production box) but seems to be something
there.
> Some negotiation of congestion window happens and then 3 tcp timeouts.
> Like I said, it's not every time.
>
> Strange.
>
> Scott Irey
> Network & Telecom Systems Engineer
> Oakland University
> Office: 248.370.2808
> Mobile: 248.505.9827
>
> -----Original Message-----
> From: matthn at gmail.com [mailto:matthn at gmail.com] On Behalf Of Nick
> Matthews
> Sent: Tuesday, March 16, 2010 1:47 PM
> To: Scott Irey
> Cc: cisco-voip at puck.nether.net
> Subject: Re: [cisco-voip] h323 to call manager inbound calls randomly
> complete
>
> Looking at this from a packet capture in a TCP level instead of odd
> H323 debugs will be much more helpful.
>
> -nick
>
> On Mon, Mar 15, 2010 at 10:12 AM, Scott Irey <irey at oakland.edu> wrote:
>> Hello,
>>
>>
>>
>> Having a problem with inbound calls from TDM completing h323 to cucm
> 7.1.
>> Seems to be fairly random, works once or twice, next call fails, cycle
>> repeats. Doing a debug CCH323 all, here is where a call fails and never
>> connects.
>>
>>
>>
>> ar 15 10:51:35.455: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch:
>> Timer[CCH323_SOCK_WRITE_BLOCKED_TIMER] expired
>>
>> Mar 15 10:51:35.455:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: fd 2
>>
>> Mar 15 10:51:35.455:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_start_sock_blocked_timer: fd 2
>>
>> Mar 15 10:51:35.455:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: Retry, fd=2
>>
>> Mar 15 10:51:35.555: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch:
>> Timer[CCH323_SOCK_WRITE_BLOCKED_TIMER] expired
>>
>> Mar 15 10:51:35.555:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: fd 2
>>
>> Mar 15 10:51:35.555:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_start_sock_blocked_timer: fd 2
>>
>> Mar 15 10:51:35.555:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: Retry, fd=2
>>
>> Mar 15 10:51:35.655: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch:
>> Timer[CCH323_SOCK_WRITE_BLOCKED_TIMER] expired
>>
>> Mar 15 10:51:35.655:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: fd 2
>>
>> Mar 15 10:51:35.655:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_start_sock_blocked_timer: fd 2
>>
>> Mar 15 10:51:35.655:
>> //-1/xxxxxxxxxxxx/H323/h323_gw_sock_block_timer_expired: Retry, fd=2
>>
>> Mar 15 10:51:35.755: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch:
>> Timer[CCH323_SOCK_WRITE_BLOCKED_TIMER] expired
>>
>>
>>
>> Repeats this for a bit and then sends a disconnect. And I get operator
> from
>> the telco.
>>
>>
>>
>> Any one seen something like this before where some calls complete and
> some
>> don't?
>>
>> Scott Irey
>>
>> Network & Telecom Systems Engineer
>>
>> Oakland University
>>
>> Office: 248.370.2808
>>
>> Mobile: 248.505.9827
>>
>>
>>
>> _______________________________________________
>> cisco-voip mailing list
>> cisco-voip at puck.nether.net
>> https://puck.nether.net/mailman/listinfo/cisco-voip
>>
>>
> _______________________________________________
> cisco-voip mailing list
> cisco-voip at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-voip
>