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

Fri Mar 19 12:32:07 EDT 2010

Blech.
   Since it's not in production, what are the chances you'd be willing
to bypass the FWSM completely for a couple tests? Since you're using
the loopback of the router, as long as you fix IP routing, you don't
need to change any voice related configuration at all to do this.

-Peter

On Thu, Mar 18, 2010 at 1:53 PM, Scott Irey <irey at oakland.edu> wrote:
> 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
>>
>