BCM 50 to Cisco CallManager using H323

[twscrb]

I'm trying to connect a BCM50 to a Cisco CallManager using an H323 trunk.
The configuration works perfectly if the call is initiated from the BCM50 side.
However, if the call is initiated from the Cisco side, there is no audio.
I can hear and interact with the BCM50's IVR/auto-attendant but after the call is transferred
and the dialed phone answers, there is no audio from either side.

Let me know if anybody has had any experience with this configuration.

 

[norstarboy125]

sounds to me that you need to open some rtp ports on the router.

Jeremy J. Carter
Charm City Communications

http://www.charmcitycommunications.com

Norstar. BCM. CS1000 Programmer

 

[twscrb]

From looking at the traces, we can see that no packets are being dropped between the ASAs.

However, the message that we see from the BCM50 is: 'udp port 51000 unreachable'

From our other offices that are using Panasonic systems we can make/receive calls to the BCM50 using H323 with no problems -- but with the Cisco CallManager the H323 configuration seems to require a different touch.

 

[norstarboy125]

These ports should be open 28000-28255 and 51000-51200.

Jeremy J. Carter
Charm City Communications

http://www.charmcitycommunications.com

Norstar. BCM. CS1000 Programmer

 

[twscrb]

@norstarboy125

I will verify the ports.

Any opinion as whether SIP would work better than H323 for the connection between CallManager and the BCM50?
We don't have the SIP license so I just wanted to know if that might be a better configuration.

 

[Firebird Scrambler]

I've just answered another thread with an answer that I think might also apply to you?.

CS1000: no ringback tone on calls across SIP trunks caused by a Cisco router fault (PMTUD)

Problem scenario:
A network of CS1000E rls 6 systems connected via SIP virtual trunks
User at Node A calls a user at Node B and does not hear any ringback tone, although the target set is ringing. After 32 seconds ringback tone is suddenly given to the caller

Examination of packet captures showed that Node B was sending the '180 Ringing' message but it was not getting through to Node A. After resending the '180 Ringing' six times Node B sent a '500 Server Internal Error' packet which did get through to Node A. On receipt of this message Node A resent the SIP Invite and this time the '180 Ringing' response was received as expected and ringback tone was heard by the caller, 32 seconds after the original SIP Invite was sent.

The '180 Ringing' packets that failed to get through to Node A had a size of 1485 bytes. The one that did get through after the second SIP Invite was much smaller - about 600 bytes.

The customer's network was using GRE Tunnelling, which added an overhead of 24 bytes to each packet, so the maximum allowable packet size on the network was 1476 bytes, rather than the MTU size of 1500 set on the CS1000 nodes.
Note that the MTU of 1500 excludes the 14 byte Ethernet header, so a packet seen as 1485 bytes in Wireshark is 1471 bytes as far as the routers are concerned.
The network routers were configured to reject packets over the allowable limit of 1476 bytes and send a fragmentation request to the originator. This fragmentation mechanism was seen to be working for larger packets.
The 1485 (1471) byte packets were below the fragmentation threshold but were nonetheless being dropped in the network.

Investigation by the customer's network manager found that Path MTU Discovery on the 7200 routers was 'broken'. He believes that this is a bug in the Cisco IOS. PMTUD was turned off and that resolved the problem.


All the best

Firebird Scrambler
Meridian 1 / Succession and BCM / Norstar Programmer in the UK

http://www.linkedin.com/in/davidbromley

If it's working, then leave it alone!.

 

[twscrb]

@firebirdscrambler

Thanks for the direction -- but from our traces we don't see anything that would suggest that packets are being dropped.

It seems more that after the call is setup between both sites that the Nortel BCM50 is not communicating on udp port 51000.
It seems as though the Nortel phones might be rejecting the voice traffic.

@norstarboy125

We've confirmed that the ports you listed are open on the BCM50. We've also confirmed that no 'necessary' ports are being blocked on the network.

 

[SupportDude]

Can you post a WireShark sniff or the FEPS log from the BCM?

-SD-

http://www.mysupportguy.net

 

[twscrb]

@SupportDude

It looks like my system only allows me to retrieve the feps.log file from the 'diagnosticsLogs' folder downloaded from the BCM50 Element Manager and not by going to

http://xx.xx.xx.xx/support/feps.log

I'm on release 2.0.2.05e

Let me know if that feps.log version would work.

 

[SupportDude]

Yes.
That would work.
Make a couple of test calls, then download the log.
Include time of call, calling party number, and called party number.

-SD-

http://www.mysupportguy.net

 

[khaman]

I ran into issues with Nortel to Cisco and within the Cisco Call Manager there was an option to terminate the media stream. Check that out when you get a chance.

 

[twscrb]

@SupportDude

Here's the feps.log from 2 calls I made -- one at 10:31 and the other at 10:32.
Calling party: 8465; called party: 2000(auto-attendant) - then transfer to ext. 1426 (ip: 10.20.20.49)

10.70.30.10 = CallManager
10.1.50.20 = Voice Gateway
10.20.20.15 = BCM50

BCM port ranges:
RTP over UDP
6800 - 6800
28000 - 28255

UDP
20000 - 20255
51000 - 51200


2013-04-17T10:31:40.733 [INFO ] {SYS } (-1) - 7232 ----- v===============================================v
2013-04-17T10:31:40.734 [INFO ] {H323} (-1) - 7233 0 incoming call m_hsCall=0x107dddec
2013-04-17T10:31:40.736 [INFO ] {H323} (-1) - 7234 0 cH323CallStateNull::EvFastStartSetup()
2013-04-17T10:31:40.739 [INFO ] {H323} (-1) - 7235 0 Null:ffering: H323 version 5
2013-04-17T10:31:40.739 [INFO ] {SYS } (-1) - 7236 ----- GKAgent::determineEndpointMcdnCaps, vendorInfo.productID=CiscoCallManager, vendorInfo.versionID=1, eMcdnCaps=0
2013-04-17T10:31:40.741 [INFO ] {H323} (-1) - 7237 0 <<--[Msg]H323 Recv SETUP crv=32963(195) FastStart calledDN=2000 callingIP=10.70.30.10:1720 callingEndpoint=CiscoCallManager 1 MCDNcaps=0
2013-04-17T10:31:40.742 [INFO ] {CP } (-1) - 7238 0 DS30terminal 0x108285d8 allocated - count is now 1
2013-04-17T10:31:40.743 [INFO ] {H323} (-1) - 7239 0 cH323MediaCtl recv SetDestination
2013-04-17T10:31:40.743 [INFO ] {H323} (-1) - 7240 0 cH323MediaCtl from [Null] to [Idle].
2013-04-17T10:31:40.744 [INFO ] {H323} (-1) - 7241 0 -->>[Msg]H323 Send PROCEEDING
2013-04-17T10:31:40.747 [INFO ] {H323} (-1) - 7242 0 cH323MediaCtl recv EvIncomingFastStart
2013-04-17T10:31:40.748 [INFO ] {H323} (-1) - 7243 0 Incoming FastStart capabilities:
2013-04-17T10:31:40.749 [INFO ] {H323} (-1) - 7244 0 Transport IP Address=10.1.50.20:0
2013-04-17T10:31:40.749 [INFO ] {H323} (-1) - 7245 0 g711u(2/666)
2013-04-17T10:31:40.752 [INFO ] {H323} (-1) - 7246 0 Changing our transport from 0.0.0.0:0 to 10.1.50.20:22402 in cH323MediaCtl::setOurCapsFromSetup()
2013-04-17T10:31:40.753 [INFO ] {H323} (-1) - 7247 0 cH323MediaCtl from [Idle] to [FastStartInfoReceived].
2013-04-17T10:31:40.754 [INFO ] {H323} (-1) - 7248 0 cH323Call from [Null] to [IncoPresent]
2013-04-17T10:31:40.754 [INFO ] {CP } (-1) - 7249 0 -->>[Msg]DS30 Send (Call) SETUP calledDN=2000 calledNPI_TON=TON_NPI_UNKNOWN_UNKNOWN CallingDN=8465 callingNPI_TON=TON_NPI_UNKNOWN_UNKNOWN
2013-04-17T10:31:40.755 [INFO ] {CP } (-1) - 7250 0 Call from [Null Outgoing] to [Call Initiated].
2013-04-17T10:31:40.909 [INFO ] {H323} (-1) - 7251 0 cH323MediaCtl recv GetCapabilities
2013-04-17T10:31:40.914 [INFO ] {H323} (-1) - 7252 0 cH323MediaCtl send AckCapabilities (1), m_bComplete=1
2013-04-17T10:31:40.914 [INFO ] {H323} (-1) - 7253 0 Transport IP Address=10.1.50.20:22402
2013-04-17T10:31:40.915 [INFO ] {H323} (-1) - 7254 0 g711u(2/666)
2013-04-17T10:31:40.945 [INFO ] {H323} (-1) - 7255 0 cH323MediaCtl recv Connect RxTx
2013-04-17T10:31:40.946 [INFO ] {H323} (-1) - 7256 0 cH323MediaCtl recv EnableOutboundStream
2013-04-17T10:31:40.953 [INFO ] {CP } (-1) - 7257 0 <<--[Msg]DS30 Recv (Call) ALERTING
2013-04-17T10:31:40.954 [INFO ] {CP } (-1) - 7258 0 Call from [Call Initiated] to [Call Delivered].
2013-04-17T10:31:40.956 [INFO ] {H323} (-1) - 7259 0 cH323AddressEventQueue::seliCallback
2013-04-17T10:31:40.956 [INFO ] {H323} (-1) - 7260 0 cH323Call from [IncoPresent] to [IncoReceived]
2013-04-17T10:31:40.957 [INFO ] {H323} (-1) - 7261 0 cH323MediaCtl recv EvAcceptIncomingFastStartInAlerting
2013-04-17T10:31:40.957 [INFO ] {H323} (-1) - 7262 0 cH323MediaCtl from [FastStartInfoReceived] to [FastStartAckSent].
2013-04-17T10:31:40.959 [INFO ] {H323} (-1) - 7263 0 cH323MediaCtl recv FastStart
2013-04-17T10:31:40.959 [INFO ] {H323} (-1) - 7264 0 cH323InboundGuard from [Disabled] to [Enabled].
2013-04-17T10:31:40.971 [INFO ] {H323} (-1) - 7265 0 cH323MediaCtl from [FastStartAckSent] to [ConnectingFSChannels].
2013-04-17T10:31:40.971 [INFO ] {H323} (-1) - 7266 0 cH323OutboundGuard from [Initial] to [WaitH245].
2013-04-17T10:31:40.972 [INFO ] {H323} (-1) - 7267 0 cH323LogChan from [OutboundInitial] to [OutboundIdle].
2013-04-17T10:31:40.973 [INFO ] {H323} (-1) - 7268 0 RV handle 0x107a6444 opened - handle count is now 1
2013-04-17T10:31:40.974 [INFO ] {H323} (-1) - 7269 0 SetOurRTCP ip = 10.1.50.20:22403
2013-04-17T10:31:40.974 [INFO ] {H323} (-1) - 7270 0 SetOurRTP ip = 10.1.50.20:22402
2013-04-17T10:31:40.975 [INFO ] {H323} (-1) - 7271 0 IB FastStart Channel: ip = 10.1.50.20 data:22402 ctrl:22403 for handle 0x107a6444
2013-04-17T10:31:40.976 [INFO ] {H323} (-1) - 7272 0 cH323LogChan from [InboundInitial] to [InboundPreConnected].
2013-04-17T10:31:40.976 [INFO ] {H323} (-1) - 7273 0 RV handle 0x107a65dc opened - handle count is now 2
2013-04-17T10:31:40.977 [INFO ] {H323} (-1) - 7274 0 SetOurRTCP ip = 10.1.50.20:22403
2013-04-17T10:31:40.978 [INFO ] {H323} (-1) - 7275 0 cH323LogChan from [OutboundIdle] to [OutboundFastStartOffering].
2013-04-17T10:31:40.979 [INFO ] {H323} (-1) - 7276 0 OfferOutbound ip = 10.1.50.20 data:0 ctrl:22403
2013-04-17T10:31:40.979 [INFO ] {H323} (-1) - 7277 0 cH323MediaCtl send OfferOutboundStream g711Ulaw64k, fpp=2
2013-04-17T10:31:40.984 [INFO ] {H323} (-1) - 7278 0 -->>[Msg]H323 Send ALERTING
2013-04-17T10:31:40.989 [INFO ] {H323} (-1) - 7279 0 H245 send FACILITY(startH245)
2013-04-17T10:31:40.993 [INFO ] {H323} (-1) - 7280 0 cmCallConnectControl successful
2013-04-17T10:31:40.995 [INFO ] {H323} (-1) - 7281 0 cH323MediaCtl recv StartInboundStream g711Ulaw64k, fpp=2, ta=10.25.20.15:28020,28021
2013-04-17T10:31:40.995 [INFO ] {H323} (-1) - 7282 0 cH323LogChan from [InboundPreConnected] to [InboundConnected].
2013-04-17T10:31:40.996 [INFO ] {H323} (-1) - 7283 0 Media connected (Inbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:31:40.998 [INFO ] {H323} (-1) - 7284 0 cH323MediaCtl send AckStartInboundStream
2013-04-17T10:31:41.031 [INFO ] {H323} (-1) - 7285 0 cH323MediaCtl recv AckOfferOutboundStream ip = 10.25.20.15 data:28020 ctrl:28021
2013-04-17T10:31:41.032 [INFO ] {H323} (-1) - 7286 0 cH323LogChan from [OutboundFastStartOffering] to [OutboundConnected].
2013-04-17T10:31:41.032 [INFO ] {H323} (-1) - 7287 0 Media connected (Outbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:31:41.189 [INFO ] {CP } (-1) - 7288 0 <<--[Msg]DS30 Recv (Call) CONNECT
2013-04-17T10:31:41.189 [INFO ] {CP } (-1) - 7289 0 Call from [Call Delivered] to [Active].
2013-04-17T10:31:41.200 [INFO ] {H323} (-1) - 7290 0 cH323AddressEventQueue::seliCallback
2013-04-17T10:31:41.201 [INFO ] {H323} (-1) - 7291 0 cH323Call from [IncoReceived] to [WaitingConnectedCallSetup]
2013-04-17T10:31:41.202 [INFO ] {H323} (-1) - 7292 0 cH323Call::answerIncomingCall() m_bFastStart=1 m_fastStarted=1
2013-04-17T10:31:41.202 [INFO ] {H323} (-1) - 7293 0 cH323MediaCtl recv EvAcceptIncomingFastStartInConnect
2013-04-17T10:31:41.203 [INFO ] {H323} (-1) - 7294 0 cH323MediaCtlState::EvAcceptIncomingFastStartInConnect not valid in state ConnectingFSChannels
2013-04-17T10:31:41.203 [INFO ] {H323} (-1) - 7295 0 cH323Call::answerIncomingCall() completeAnswerCall=1
2013-04-17T10:31:41.204 [INFO ] {H323} (-1) - 7296 0 -->>[Msg]H323 Send CONNECT
2013-04-17T10:31:41.209 [INFO ] {H323} (-1) - 7297 0 H323 call successful (FastStart)
2013-04-17T10:31:41.223 [INFO ] {H323} (-1) - 7298 0 cH323Call from [WaitingConnectedCallSetup] to [Active]
2013-04-17T10:31:41.225 [INFO ] {H323} (-1) - 7299 0 H245 recv H245Connected
2013-04-17T10:31:41.226 [INFO ] {H323} (-1) - 7300 0 cH323OutboundGuard from [WaitH245] to [Enabling].
2013-04-17T10:31:41.227 [INFO ] {H323} (-1) - 7301 0 H245 send TCS(g711u(2/6)) using DesiredFpp
2013-04-17T10:31:41.241 [INFO ] {H323} (-1) - 7302 0 H245 send MSDetermine(61)
2013-04-17T10:31:41.243 [INFO ] {H323} (-1) - 7303 0 cH323Capabilities from [Initial] to [Negotiating].
2013-04-17T10:31:41.247 [INFO ] {H323} (-1) - 7304 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:31:41.247 [INFO ] {H323} (-1) - 7305 0 H245 send TCS ACK
2013-04-17T10:31:41.249 [INFO ] {H323} (-1) - 7306 0 Filtered: g711u(3/666)
2013-04-17T10:31:41.319 [INFO ] {H323} (-1) - 7307 0 H245 recv TCS ACK
2013-04-17T10:31:41.344 [INFO ] {H323} (-1) - 7308 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:31:41.345 [INFO ] {H323} (-1) - 7309 0 H245 send TCS ACK
2013-04-17T10:31:41.346 [INFO ] {H323} (-1) - 7310 0 Filtered: g711u(3/666)
2013-04-17T10:31:41.348 [INFO ] {H323} (-1) - 7311 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:31:41.349 [INFO ] {H323} (-1) - 7312 0 cH323Capabilities from [Negotiating] to [Idle].
2013-04-17T10:31:41.351 [INFO ] {H323} (-1) - 7313 0 LastSent: g711u(2/6)
2013-04-17T10:31:41.352 [INFO ] {H323} (-1) - 7314 0 LastRecvd: g711u(3/666)
2013-04-17T10:31:41.352 [INFO ] {H323} (-1) - 7315 0 H245 negotiation succeeded
2013-04-17T10:31:41.353 [INFO ] {H323} (-1) - 7316 0 Selected capability: g711u(3/666)
2013-04-17T10:31:41.353 [INFO ] {H323} (-1) - 7317 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:31:41.354 [INFO ] {H323} (-1) - 7318 0 cH323OutboundGuard from [Enabling] to [Enabled].
2013-04-17T10:31:41.355 [INFO ] {H323} (-1) - 7319 0 cH323MediaCtl HandleDropToSlowStart
2013-04-17T10:31:41.356 [INFO ] {H323} (-1) - 7320 0 cH323MediaCtl send ForwardCapabilities (1), m_bComplete=1
2013-04-17T10:31:41.356 [INFO ] {H323} (-1) - 7321 0 Transport IP Address=0.0.0.0:0
2013-04-17T10:31:41.357 [INFO ] {H323} (-1) - 7322 0 g711u(2/666)
2013-04-17T10:31:41.358 [INFO ] {H323} (-1) - 7323 0 cH323MediaCtl from [ConnectingFSChannels] to [Active].
2013-04-17T10:31:41.358 [INFO ] {H323} (-1) - 7324 0 StateConnected::CallControlConnected
2013-04-17T10:31:52.548 [INFO ] {H323} (-1) - 7325 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:31:52.553 [INFO ] {CP } (-1) - 7326 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:31:53.395 [INFO ] {H323} (-1) - 7327 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:31:53.395 [INFO ] {CP } (-1) - 7328 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:31:53.774 [INFO ] {H323} (-1) - 7329 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:31:53.775 [INFO ] {CP } (-1) - 7330 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:31:54.012 [INFO ] {H323} (-1) - 7331 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:31:54.013 [INFO ] {CP } (-1) - 7332 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:31:56.034 [INFO ] {H323} (-1) - 7333 0 cH323MediaCtl recv GetCapabilities
2013-04-17T10:31:56.037 [INFO ] {H323} (-1) - 7334 0 cH323MediaCtl send AckCapabilities (1), m_bComplete=1
2013-04-17T10:31:56.037 [INFO ] {H323} (-1) - 7335 0 Transport IP Address=0.0.0.0:0
2013-04-17T10:31:56.038 [INFO ] {H323} (-1) - 7336 0 g711u(3/666)
2013-04-17T10:32:00.109 [INFO ] {H323} (-1) - 7337 0 cH323MediaCtl recv Disconnect
2013-04-17T10:32:00.122 [INFO ] {H323} (-1) - 7338 0 cH323InboundGuard from [Enabled] to [Disabled].
2013-04-17T10:32:00.122 [INFO ] {H323} (-1) - 7339 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundConnected
2013-04-17T10:32:00.124 [INFO ] {H323} (-1) - 7340 0 cH323MediaCtl recv DisableOutboundStream
2013-04-17T10:32:00.124 [INFO ] {H323} (-1) - 7341 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundConnected
2013-04-17T10:32:00.125 [INFO ] {H323} (-1) - 7342 0 cH323MediaCtl from [Active] to [WaitNegComplete].
2013-04-17T10:32:00.125 [INFO ] {H323} (-1) - 7343 0 cH323OutboundGuard from [Enabled] to [Disabling].
2013-04-17T10:32:00.126 [INFO ] {H323} (-1) - 7344 0 H245 send TCS(null)
2013-04-17T10:32:00.128 [INFO ] {H323} (-1) - 7345 0 cH323Capabilities from [Idle] to [W4NullCapsAck].
2013-04-17T10:32:00.148 [INFO ] {H323} (-1) - 7346 0 cH323MediaCtl recv StopInboundStream
2013-04-17T10:32:00.149 [INFO ] {H323} (-1) - 7347 0 cH323MediaCtl from [WaitNegComplete] to [WaitOBS_StopIBSPending].
2013-04-17T10:32:00.246 [INFO ] {H323} (-1) - 7348 0 H245 recv TCS ACK
2013-04-17T10:32:00.247 [INFO ] {H323} (-1) - 7349 0 cH323Capabilities from [W4NullCapsAck] to [Idle].
2013-04-17T10:32:00.247 [INFO ] {H323} (-1) - 7350 0 cH323OutboundGuard from [Disabling] to [W4Channel].
2013-04-17T10:32:00.248 [INFO ] {H323} (-1) - 7351 0 cH323LogChan from [OutboundConnected] to [OutboundDisabling].
2013-04-17T10:32:00.295 [INFO ] {H323} (-1) - 7352 0 <<--[Msg]H323 Recv CLC for handle 0x107a65dc
2013-04-17T10:32:00.295 [INFO ] {H323} (-1) - 7353 0 cH323LogChan from [OutboundDisabling] to [OutboundW4AckWithdraw].
2013-04-17T10:32:00.296 [INFO ] {H323} (-1) - 7354 0 RV handle 0x107a65dc closed - handle count is now 1
2013-04-17T10:32:00.299 [INFO ] {H323} (-1) - 7355 0 cH323MediaCtl from [WaitOBS_StopIBSPending] to [WaitInboundReady].
2013-04-17T10:32:00.299 [INFO ] {H323} (-1) - 7356 0 cH323LogChan from [InboundConnected] to [InboundW4Idle].
2013-04-17T10:32:00.301 [INFO ] {H323} (-1) - 7357 0 -->>[Msg]H323 Send CLC (cmChannelDrop) for handle 0x107a6444
2013-04-17T10:32:00.303 [INFO ] {H323} (-1) - 7358 0 cH323MediaCtl send WithdrawOutboundStream
2013-04-17T10:32:00.316 [INFO ] {H323} (-1) - 7359 0 cH323MediaCtl recv AckWithdrawOutboundStream
2013-04-17T10:32:00.316 [INFO ] {H323} (-1) - 7360 0 cH323LogChan from [OutboundW4AckWithdraw] to [OutboundDisabled].
2013-04-17T10:32:00.317 [INFO ] {H323} (-1) - 7361 0 cH323OutboundGuard from [W4Channel] to [Disabled].
2013-04-17T10:32:00.319 [INFO ] {H323} (-1) - 7362 0 cH323MediaCtl send AckDisableOutboundStream
2013-04-17T10:32:00.417 [INFO ] {H323} (-1) - 7363 0 <<--[Msg]H323 Recv CLC for handle 0x107a6444
2013-04-17T10:32:00.417 [INFO ] {H323} (-1) - 7364 0 cH323LogChan from [InboundW4Idle] to [InboundIdle].
2013-04-17T10:32:00.418 [INFO ] {H323} (-1) - 7365 0 RV handle 0x107a6444 closed - handle count is now 0
2013-04-17T10:32:00.419 [INFO ] {H323} (-1) - 7366 0 cH323MediaCtl from [WaitInboundReady] to [Active].
2013-04-17T10:32:00.419 [INFO ] {H323} (-1) - 7367 0 cH323MediaCtl send AckStopInboundStream
2013-04-17T10:32:00.423 [INFO ] {H323} (-1) - 7368 0 cH323MediaCtl recv Disconnected
2013-04-17T10:32:00.423 [INFO ] {H323} (-1) - 7369 0 cH323MediaCtl from [Active] to [Disconnected].
2013-04-17T10:32:00.424 [INFO ] {H323} (-1) - 7370 0 cH323MediaCtl recv Connect RxTx
2013-04-17T10:32:00.425 [INFO ] {H323} (-1) - 7371 0 cH323MediaCtl from [Disconnected] to [WaitNegComplete].
2013-04-17T10:32:00.425 [INFO ] {H323} (-1) - 7372 0 cH323InboundGuard from [Disabled] to [Enabled].
2013-04-17T10:32:00.427 [INFO ] {H323} (-1) - 7373 0 cH323MediaCtl recv StartInboundStream g711Ulaw64k, fpp=3, ta=10.20.20.49:51010,51011
2013-04-17T10:32:00.427 [INFO ] {H323} (-1) - 7374 0 cH323MediaCtl from [WaitNegComplete] to [WaitOBS_StartIBSPending].
2013-04-17T10:32:00.428 [INFO ] {H323} (-1) - 7375 0 cH323MediaCtl recv EnableOutboundStream
2013-04-17T10:32:00.428 [INFO ] {H323} (-1) - 7376 0 sending non-NULL caps to OBS
2013-04-17T10:32:00.429 [INFO ] {H323} (-1) - 7377 0 cH323OutboundGuard from [Disabled] to [Enabling].
2013-04-17T10:32:00.433 [INFO ] {H323} (-1) - 7378 0 H245 send TCS(g711u(3/6)) using DesiredFpp
2013-04-17T10:32:00.436 [INFO ] {H323} (-1) - 7379 0 H245 send MSDetermine(61)
2013-04-17T10:32:00.437 [INFO ] {H323} (-1) - 7380 0 cH323Capabilities from [Idle] to [Negotiating].
2013-04-17T10:32:00.511 [INFO ] {H323} (-1) - 7381 0 H245 recv TCS ACK
2013-04-17T10:32:00.514 [INFO ] {H323} (-1) - 7382 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:32:00.514 [INFO ] {H323} (-1) - 7383 0 cH323Capabilities from [Negotiating] to [Idle].
2013-04-17T10:32:00.515 [INFO ] {H323} (-1) - 7384 0 LastSent: g711u(3/6)
2013-04-17T10:32:00.515 [INFO ] {H323} (-1) - 7385 0 LastRecvd: g711u(3/666)
2013-04-17T10:32:00.515 [INFO ] {H323} (-1) - 7386 0 H245 negotiation succeeded
2013-04-17T10:32:00.516 [INFO ] {H323} (-1) - 7387 0 Selected capability: g711u(3/666)
2013-04-17T10:32:00.516 [INFO ] {H323} (-1) - 7388 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:32:00.517 [INFO ] {H323} (-1) - 7389 0 cH323OutboundGuard from [Enabling] to [Enabled].
2013-04-17T10:32:00.517 [INFO ] {H323} (-1) - 7390 0 cH323LogChan from [OutboundDisabled] to [OutboundIdle].
2013-04-17T10:32:00.518 [INFO ] {H323} (-1) - 7391 0 cH323MediaCtl from [WaitOBS_StartIBSPending] to [WaitInboundReady].
2013-04-17T10:32:00.519 [INFO ] {H323} (-1) - 7392 0 cH323LogChan from [InboundIdle] to [InboundConnecting].
2013-04-17T10:32:00.519 [INFO ] {H323} (-1) - 7393 0 RV handle 0x107a6774 opened - handle count is now 1
2013-04-17T10:32:00.521 [INFO ] {H323} (-1) - 7394 0 -->>[Msg]H323 Send OLC ip = 10.20.20.49 data:51010 ctrl:51011 for handle 0x107a6774
2013-04-17T10:32:00.521 [INFO ] {H323} (-1) - 7395 0 Set RTCP address ip = 10.20.20.49:51011 for handle 0x107a6774
2013-04-17T10:32:00.522 [INFO ] {H323} (-1) - 7396 0 -->>[Msg]H323 Send OLC g711Ulaw64k, fpp=3
2013-04-17T10:32:00.543 [INFO ] {H323} (-1) - 7397 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:32:00.543 [INFO ] {H323} (-1) - 7398 0 H245 send TCS ACK
2013-04-17T10:32:00.545 [INFO ] {H323} (-1) - 7399 0 Filtered: g711u(3/666)
2013-04-17T10:32:00.546 [INFO ] {H323} (-1) - 7400 0 H245 send MSDetermine(59)
2013-04-17T10:32:00.547 [INFO ] {H323} (-1) - 7401 0 cH323Capabilities from [Idle] to [RecvdNewCaps].
2013-04-17T10:32:00.629 [INFO ] {H323} (-1) - 7402 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:32:00.630 [INFO ] {H323} (-1) - 7403 0 cH323Capabilities from [RecvdNewCaps] to [Idle].
2013-04-17T10:32:00.631 [INFO ] {H323} (-1) - 7404 0 LastSent: g711u(3/6)
2013-04-17T10:32:00.631 [INFO ] {H323} (-1) - 7405 0 LastRecvd: g711u(3/666)
2013-04-17T10:32:00.632 [INFO ] {H323} (-1) - 7406 0 H245 negotiation succeeded
2013-04-17T10:32:00.632 [INFO ] {H323} (-1) - 7407 0 Selected capability: g711u(3/666)
2013-04-17T10:32:00.633 [INFO ] {H323} (-1) - 7408 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:32:00.641 [INFO ] {H323} (-1) - 7409 0 RV handle 0x107a690c opened - handle count is now 2
2013-04-17T10:32:00.642 [INFO ] {H323} (-1) - 7410 0 SetOurRTCP ip = 10.70.30.10:4001
2013-04-17T10:32:00.643 [INFO ] {H323} (-1) - 7411 0 <<--[Msg]H323 Recv OLC for handle 0x107a690c
2013-04-17T10:32:00.644 [INFO ] {H323} (-1) - 7412 0 cH323LogChan from [OutboundIdle] to [OutboundOffering].
2013-04-17T10:32:00.644 [INFO ] {H323} (-1) - 7413 0 ForwardCapabilities: epfCaps are complete and not renegotiating, not forwarding
2013-04-17T10:32:00.645 [INFO ] {H323} (-1) - 7414 0 OfferOutbound ip = 10.70.30.10 data:0 ctrl:4001
2013-04-17T10:32:00.645 [INFO ] {H323} (-1) - 7415 0 cH323MediaCtl send OfferOutboundStream g711Ulaw64k, fpp=2
2013-04-17T10:32:00.648 [INFO ] {H323} (-1) - 7416 0 SetOurRTCP ip = 10.1.50.20:22949
2013-04-17T10:32:00.649 [INFO ] {H323} (-1) - 7417 0 SetOurRTP ip = 10.1.50.20:22948
2013-04-17T10:32:00.649 [INFO ] {H323} (-1) - 7418 0 <<--[Msg]H323 Recv OLC ACK
2013-04-17T10:32:00.651 [INFO ] {H323} (-1) - 7419 0 cH323LogChan from [InboundConnecting] to [InboundConnected].
2013-04-17T10:32:00.651 [INFO ] {H323} (-1) - 7420 0 IB SlowStart channel: ip = 10.1.50.20 data:22948 ctrl:22949 for handle 0x107a6774
2013-04-17T10:32:00.652 [INFO ] {H323} (-1) - 7421 0 Recv OLC ACK: ip = 10.1.50.20 data:22948 ctrl:22949 for handle 0x107a6774
2013-04-17T10:32:00.652 [INFO ] {H323} (-1) - 7422 0 Media connected (Inbound); codec=0(g711Ulaw64k) fpp=3
2013-04-17T10:32:00.653 [INFO ] {H323} (-1) - 7423 0 ForwardCapabilities: epfCaps are complete and not renegotiating, not forwarding
2013-04-17T10:32:00.656 [INFO ] {H323} (-1) - 7424 0 cH323MediaCtl from [WaitInboundReady] to [Active].
2013-04-17T10:32:00.656 [INFO ] {H323} (-1) - 7425 0 cH323MediaCtl send AckStartInboundStream
2013-04-17T10:32:00.678 [INFO ] {H323} (-1) - 7426 0 cH323MediaCtl recv AckOfferOutboundStream ip = 10.20.20.49 data:51010 ctrl:51011
2013-04-17T10:32:00.679 [INFO ] {H323} (-1) - 7427 0 cH323LogChan from [OutboundOffering] to [OutboundAnswering].
2013-04-17T10:32:00.680 [INFO ] {H323} (-1) - 7428 0 Set RTP address ip = 10.20.20.49:51010 for handle 0x107a690c
2013-04-17T10:32:00.685 [INFO ] {H323} (-1) - 7429 0 Set RTCP address ip = 10.20.20.49:51011 for handle 0x107a690c
2013-04-17T10:32:00.686 [INFO ] {H323} (-1) - 7430 0 -->>[Msg]H323 Send OLC ACK (cmChannelAnswer) for handle 0x107a690c
2013-04-17T10:32:00.688 [INFO ] {H323} (-1) - 7431 0 Media connected (Outbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:32:00.688 [INFO ] {H323} (-1) - 7432 0 cH323LogChan from [OutboundAnswering] to [OutboundConnected].
2013-04-17T10:32:16.289 [INFO ] {H323} (-1) - 7433 0 <<--[Msg]H323 Recv CLC for handle 0x107a690c
2013-04-17T10:32:16.289 [INFO ] {H323} (-1) - 7434 0 cH323LogChan from [OutboundConnected] to [OutboundDisconnecting].
2013-04-17T10:32:16.291 [INFO ] {H323} (-1) - 7435 0 RV handle 0x107a690c closed - handle count is now 1
2013-04-17T10:32:16.291 [INFO ] {H323} (-1) - 7436 0 cH323MediaCtl send WithdrawOutboundStream
2013-04-17T10:32:16.299 [INFO ] {H323} (-1) - 7437 0 cH323MediaCtl recv AckWithdrawOutboundStream
2013-04-17T10:32:16.302 [INFO ] {H323} (-1) - 7438 0 cH323LogChan from [OutboundDisconnecting] to [OutboundIdle].
2013-04-17T10:32:16.374 [INFO ] {H323} (-1) - 7439 0 <<--[Msg]H323 Recv CLC for handle 0x107a6774
2013-04-17T10:32:16.374 [INFO ] {H323} (-1) - 7440 0 cH323LogChan from [InboundConnected] to [InboundW4Stop].
2013-04-17T10:32:16.375 [INFO ] {H323} (-1) - 7441 0 RV handle 0x107a6774 closed - handle count is now 0
2013-04-17T10:32:16.499 [INFO ] {H323} (-1) - 7442 0 cH323Call from [Active] to [FarRlsWaitingIdle]
2013-04-17T10:32:16.500 [INFO ] {H323} (-1) - 7443 0 cH323MediaCtl recv Release
2013-04-17T10:32:16.501 [INFO ] {H323} (-1) - 7444 0 cH323MediaCtl from [Active] to [Releasing].
2013-04-17T10:32:16.501 [INFO ] {H323} (-1) - 7445 0 cH323OutboundGuard from [Enabled] to [Releasing].
2013-04-17T10:32:16.502 [INFO ] {H323} (-1) - 7446 0 There was no release complete reason in the RELCOM UUIE
2013-04-17T10:32:16.503 [INFO ] {H323} (-1) - 7447 0 <<--[Msg]H323 Recv RELEASE [ reason is: cmReasonTypeUndefinedReason cause is: Normal call clearing ]
2013-04-17T10:32:16.503 [INFO ] {H323} (-1) - 7448 0 DS30 RELEASE cause [ Normal call clearing ]
2013-04-17T10:32:16.504 [INFO ] {H323} (-1) - 7449 0 cH323MediaCtl send NotifyDisconnect
2013-04-17T10:32:16.505 [INFO ] {H323} (-1) - 7450 0 cH323Call from [FarRlsWaitingIdle] to [FarRlsWaitingMediaDisconnected]
2013-04-17T10:32:16.506 [INFO ] {H323} (-1) - 7451 0 cH323MediaCtl recv Disconnect
2013-04-17T10:32:16.507 [INFO ] {H323} (-1) - 7452 0 cH323MediaCtl recv DisableOutboundStream
2013-04-17T10:32:16.508 [INFO ] {H323} (-1) - 7453 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundW4Stop
2013-04-17T10:32:16.508 [INFO ] {H323} (-1) - 7454 0 cH323LogChan from [OutboundIdle] to [OutboundDisabled].
2013-04-17T10:32:16.514 [INFO ] {H323} (-1) - 7455 0 cH323OutboundGuard from [Releasing] to [Dead].
2013-04-17T10:32:16.515 [INFO ] {H323} (-1) - 7456 0 cH323MediaCtl send AckDisableOutboundStream
2013-04-17T10:32:16.526 [INFO ] {H323} (-1) - 7457 0 cH323MediaCtl recv StopInboundStream
2013-04-17T10:32:16.526 [INFO ] {H323} (-1) - 7458 0 cH323LogChan from [InboundW4Stop] to [InboundIdle].
2013-04-17T10:32:16.528 [INFO ] {H323} (-1) - 7459 0 cH323MediaCtl send AckStopInboundStream
2013-04-17T10:32:16.529 [INFO ] {H323} (-1) - 7460 0 cH323MediaCtl recv Disconnected
2013-04-17T10:32:16.529 [INFO ] {H323} (-1) - 7461 0 cH323MediaCtl from [Releasing] to [Null].
2013-04-17T10:32:16.537 [INFO ] {CP } (-1) - 7462 0 Call from [Active] to [FarEndRlsPending Waiting PathGone].
2013-04-17T10:32:16.538 [INFO ] {H323} (-1) - 7463 0 calling cmCallClose m_hsCall=0x107dddec
2013-04-17T10:32:16.541 [INFO ] {CP } (-1) - 7464 0 Call from [FarEndRlsPending Waiting PathGone] to [Waiting Release].
2013-04-17T10:32:16.541 [INFO ] {CP } (-1) - 7465 0 -->>[Msg]DS30 Send (Call) RELEASE
2013-04-17T10:32:16.566 [INFO ] {H323} (-1) - 7466 0 cH323MediaCtl from [Null] to [-Destroyed-].
2013-04-17T10:32:16.597 [INFO ] {CP } (-1) - 7467 0 Call from [Waiting Release] to [Null Incoming].
2013-04-17T10:32:16.598 [INFO ] {CP } (-1) - 7468 0 DS30terminal 0x108285d8 freed - count is now 0
2013-04-17T10:32:16.598 [INFO ] {CP } (-1) - 7469 0 ^===============================================^
2013-04-17T10:32:26.102 [INFO ] {SYS } (-1) - 7470 ----- v===============================================v
2013-04-17T10:32:26.102 [INFO ] {H323} (-1) - 7471 0 incoming call m_hsCall=0x107de0bc
2013-04-17T10:32:26.105 [INFO ] {H323} (-1) - 7472 0 cH323CallStateNull::EvFastStartSetup()
2013-04-17T10:32:26.107 [INFO ] {H323} (-1) - 7473 0 Null:ffering: H323 version 5
2013-04-17T10:32:26.108 [INFO ] {SYS } (-1) - 7474 ----- GKAgent::determineEndpointMcdnCaps, vendorInfo.productID=CiscoCallManager, vendorInfo.versionID=1, eMcdnCaps=0
2013-04-17T10:32:26.108 [INFO ] {H323} (-1) - 7475 0 <<--[Msg]H323 Recv SETUP crv=32964(196) FastStart calledDN=2000 callingIP=10.70.30.10:1720 callingEndpoint=CiscoCallManager 1 MCDNcaps=0
2013-04-17T10:32:26.109 [INFO ] {CP } (-1) - 7476 0 DS30terminal 0x108285d8 allocated - count is now 1
2013-04-17T10:32:26.112 [INFO ] {H323} (-1) - 7477 0 cH323MediaCtl recv SetDestination
2013-04-17T10:32:26.113 [INFO ] {H323} (-1) - 7478 0 cH323MediaCtl from [Null] to [Idle].
2013-04-17T10:32:26.113 [INFO ] {H323} (-1) - 7479 0 -->>[Msg]H323 Send PROCEEDING
2013-04-17T10:32:26.116 [INFO ] {H323} (-1) - 7480 0 cH323MediaCtl recv EvIncomingFastStart
2013-04-17T10:32:26.117 [INFO ] {H323} (-1) - 7481 0 Incoming FastStart capabilities:
2013-04-17T10:32:26.118 [INFO ] {H323} (-1) - 7482 0 Transport IP Address=10.1.50.20:0
2013-04-17T10:32:26.118 [INFO ] {H323} (-1) - 7483 0 g711u(2/666)
2013-04-17T10:32:26.119 [INFO ] {H323} (-1) - 7484 0 Changing our transport from 0.0.0.0:0 to 10.1.50.20:28324 in cH323MediaCtl::setOurCapsFromSetup()
2013-04-17T10:32:26.120 [INFO ] {H323} (-1) - 7485 0 cH323MediaCtl from [Idle] to [FastStartInfoReceived].
2013-04-17T10:32:26.122 [INFO ] {H323} (-1) - 7486 0 cH323Call from [Null] to [IncoPresent]
2013-04-17T10:32:26.122 [INFO ] {CP } (-1) - 7487 0 -->>[Msg]DS30 Send (Call) SETUP calledDN=2000 calledNPI_TON=TON_NPI_UNKNOWN_UNKNOWN CallingDN=8465 callingNPI_TON=TON_NPI_UNKNOWN_UNKNOWN
2013-04-17T10:32:26.123 [INFO ] {CP } (-1) - 7488 0 Call from [Null Outgoing] to [Call Initiated].
2013-04-17T10:32:26.261 [INFO ] {H323} (-1) - 7489 0 cH323MediaCtl recv GetCapabilities
2013-04-17T10:32:26.262 [INFO ] {H323} (-1) - 7490 0 cH323MediaCtl send AckCapabilities (1), m_bComplete=1
2013-04-17T10:32:26.262 [INFO ] {H323} (-1) - 7491 0 Transport IP Address=10.1.50.20:28324
2013-04-17T10:32:26.263 [INFO ] {H323} (-1) - 7492 0 g711u(2/666)
2013-04-17T10:32:26.319 [INFO ] {H323} (-1) - 7493 0 cH323MediaCtl recv Connect RxTx
2013-04-17T10:32:26.321 [INFO ] {H323} (-1) - 7494 0 cH323MediaCtl recv EnableOutboundStream
2013-04-17T10:32:26.325 [INFO ] {CP } (-1) - 7495 0 <<--[Msg]DS30 Recv (Call) ALERTING
2013-04-17T10:32:26.326 [INFO ] {CP } (-1) - 7496 0 Call from [Call Initiated] to [Call Delivered].
2013-04-17T10:32:26.327 [INFO ] {H323} (-1) - 7497 0 cH323AddressEventQueue::seliCallback
2013-04-17T10:32:26.328 [INFO ] {H323} (-1) - 7498 0 cH323Call from [IncoPresent] to [IncoReceived]
2013-04-17T10:32:26.328 [INFO ] {H323} (-1) - 7499 0 cH323MediaCtl recv EvAcceptIncomingFastStartInAlerting
2013-04-17T10:32:26.329 [INFO ] {H323} (-1) - 7500 0 cH323MediaCtl from [FastStartInfoReceived] to [FastStartAckSent].
2013-04-17T10:32:26.334 [INFO ] {H323} (-1) - 7501 0 cH323MediaCtl recv FastStart
2013-04-17T10:32:26.335 [INFO ] {H323} (-1) - 7502 0 cH323InboundGuard from [Disabled] to [Enabled].
2013-04-17T10:32:26.336 [INFO ] {H323} (-1) - 7503 0 cH323MediaCtl from [FastStartAckSent] to [ConnectingFSChannels].
2013-04-17T10:32:26.336 [INFO ] {H323} (-1) - 7504 0 cH323OutboundGuard from [Initial] to [WaitH245].
2013-04-17T10:32:26.337 [INFO ] {H323} (-1) - 7505 0 cH323LogChan from [OutboundInitial] to [OutboundIdle].
2013-04-17T10:32:26.337 [INFO ] {H323} (-1) - 7506 0 RV handle 0x107a6aa4 opened - handle count is now 1
2013-04-17T10:32:26.338 [INFO ] {H323} (-1) - 7507 0 SetOurRTCP ip = 10.1.50.20:28325
2013-04-17T10:32:26.339 [INFO ] {H323} (-1) - 7508 0 SetOurRTP ip = 10.1.50.20:28324
2013-04-17T10:32:26.341 [INFO ] {H323} (-1) - 7509 0 IB FastStart Channel: ip = 10.1.50.20 data:28324 ctrl:28325 for handle 0x107a6aa4
2013-04-17T10:32:26.342 [INFO ] {H323} (-1) - 7510 0 cH323LogChan from [InboundInitial] to [InboundPreConnected].
2013-04-17T10:32:26.342 [INFO ] {H323} (-1) - 7511 0 RV handle 0x107a6c3c opened - handle count is now 2
2013-04-17T10:32:26.343 [INFO ] {H323} (-1) - 7512 0 SetOurRTCP ip = 10.1.50.20:28325
2013-04-17T10:32:26.344 [INFO ] {H323} (-1) - 7513 0 cH323LogChan from [OutboundIdle] to [OutboundFastStartOffering].
2013-04-17T10:32:26.345 [INFO ] {H323} (-1) - 7514 0 OfferOutbound ip = 10.1.50.20 data:0 ctrl:28325
2013-04-17T10:32:26.345 [INFO ] {H323} (-1) - 7515 0 cH323MediaCtl send OfferOutboundStream g711Ulaw64k, fpp=2
2013-04-17T10:32:26.347 [INFO ] {H323} (-1) - 7516 0 -->>[Msg]H323 Send ALERTING
2013-04-17T10:32:26.361 [INFO ] {H323} (-1) - 7517 0 H245 send FACILITY(startH245)
2013-04-17T10:32:26.364 [INFO ] {H323} (-1) - 7518 0 cmCallConnectControl successful
2013-04-17T10:32:26.366 [INFO ] {H323} (-1) - 7519 0 cH323MediaCtl recv StartInboundStream g711Ulaw64k, fpp=2, ta=10.25.20.15:28020,28021
2013-04-17T10:32:26.367 [INFO ] {H323} (-1) - 7520 0 cH323LogChan from [InboundPreConnected] to [InboundConnected].
2013-04-17T10:32:26.367 [INFO ] {H323} (-1) - 7521 0 Media connected (Inbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:32:26.373 [INFO ] {H323} (-1) - 7522 0 cH323MediaCtl send AckStartInboundStream
2013-04-17T10:32:26.413 [INFO ] {H323} (-1) - 7523 0 cH323MediaCtl recv AckOfferOutboundStream ip = 10.25.20.15 data:28020 ctrl:28021
2013-04-17T10:32:26.415 [INFO ] {H323} (-1) - 7524 0 cH323LogChan from [OutboundFastStartOffering] to [OutboundConnected].
2013-04-17T10:32:26.416 [INFO ] {H323} (-1) - 7525 0 Media connected (Outbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:32:26.536 [INFO ] {CP } (-1) - 7526 0 <<--[Msg]DS30 Recv (Call) CONNECT
2013-04-17T10:32:26.537 [INFO ] {CP } (-1) - 7527 0 Call from [Call Delivered] to [Active].
2013-04-17T10:32:26.538 [INFO ] {H323} (-1) - 7528 0 cH323AddressEventQueue::seliCallback
2013-04-17T10:32:26.539 [INFO ] {H323} (-1) - 7529 0 cH323Call from [IncoReceived] to [WaitingConnectedCallSetup]
2013-04-17T10:32:26.539 [INFO ] {H323} (-1) - 7530 0 cH323Call::answerIncomingCall() m_bFastStart=1 m_fastStarted=1
2013-04-17T10:32:26.539 [INFO ] {H323} (-1) - 7531 0 cH323MediaCtl recv EvAcceptIncomingFastStartInConnect
2013-04-17T10:32:26.551 [INFO ] {H323} (-1) - 7532 0 cH323MediaCtlState::EvAcceptIncomingFastStartInConnect not valid in state ConnectingFSChannels
2013-04-17T10:32:26.551 [INFO ] {H323} (-1) - 7533 0 cH323Call::answerIncomingCall() completeAnswerCall=1
2013-04-17T10:32:26.551 [INFO ] {H323} (-1) - 7534 0 -->>[Msg]H323 Send CONNECT
2013-04-17T10:32:26.557 [INFO ] {H323} (-1) - 7535 0 H323 call successful (FastStart)
2013-04-17T10:32:26.558 [INFO ] {H323} (-1) - 7536 0 cH323Call from [WaitingConnectedCallSetup] to [Active]
2013-04-17T10:32:26.568 [INFO ] {H323} (-1) - 7537 0 H245 recv H245Connected
2013-04-17T10:32:26.569 [INFO ] {H323} (-1) - 7538 0 cH323OutboundGuard from [WaitH245] to [Enabling].
2013-04-17T10:32:26.571 [INFO ] {H323} (-1) - 7539 0 H245 send TCS(g711u(2/6)) using DesiredFpp
2013-04-17T10:32:26.574 [INFO ] {H323} (-1) - 7540 0 H245 send MSDetermine(61)
2013-04-17T10:32:26.576 [INFO ] {H323} (-1) - 7541 0 cH323Capabilities from [Initial] to [Negotiating].
2013-04-17T10:32:26.586 [INFO ] {H323} (-1) - 7542 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:32:26.587 [INFO ] {H323} (-1) - 7543 0 H245 send TCS ACK
2013-04-17T10:32:26.588 [INFO ] {H323} (-1) - 7544 0 Filtered: g711u(3/666)
2013-04-17T10:32:26.662 [INFO ] {H323} (-1) - 7545 0 H245 recv TCS ACK
2013-04-17T10:32:26.684 [INFO ] {H323} (-1) - 7546 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:32:26.684 [INFO ] {H323} (-1) - 7547 0 H245 send TCS ACK
2013-04-17T10:32:26.686 [INFO ] {H323} (-1) - 7548 0 Filtered: g711u(3/666)
2013-04-17T10:32:26.688 [INFO ] {H323} (-1) - 7549 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:32:26.689 [INFO ] {H323} (-1) - 7550 0 cH323Capabilities from [Negotiating] to [Idle].
2013-04-17T10:32:26.689 [INFO ] {H323} (-1) - 7551 0 LastSent: g711u(2/6)
2013-04-17T10:32:26.696 [INFO ] {H323} (-1) - 7552 0 LastRecvd: g711u(3/666)
2013-04-17T10:32:26.696 [INFO ] {H323} (-1) - 7553 0 H245 negotiation succeeded
2013-04-17T10:32:26.697 [INFO ] {H323} (-1) - 7554 0 Selected capability: g711u(3/666)
2013-04-17T10:32:26.697 [INFO ] {H323} (-1) - 7555 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:32:26.698 [INFO ] {H323} (-1) - 7556 0 cH323OutboundGuard from [Enabling] to [Enabled].
2013-04-17T10:32:26.699 [INFO ] {H323} (-1) - 7557 0 cH323MediaCtl HandleDropToSlowStart
2013-04-17T10:32:26.699 [INFO ] {H323} (-1) - 7558 0 cH323MediaCtl send ForwardCapabilities (1), m_bComplete=1
2013-04-17T10:32:26.700 [INFO ] {H323} (-1) - 7559 0 Transport IP Address=0.0.0.0:0
2013-04-17T10:32:26.701 [INFO ] {H323} (-1) - 7560 0 g711u(2/666)
2013-04-17T10:32:26.702 [INFO ] {H323} (-1) - 7561 0 cH323MediaCtl from [ConnectingFSChannels] to [Active].
2013-04-17T10:32:26.703 [INFO ] {H323} (-1) - 7562 0 StateConnected::CallControlConnected
2013-04-17T10:32:30.514 [INFO ] {H323} (-1) - 7563 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:32:30.515 [INFO ] {CP } (-1) - 7564 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:32:30.949 [INFO ] {H323} (-1) - 7565 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:32:30.949 [INFO ] {CP } (-1) - 7566 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:32:31.312 [INFO ] {H323} (-1) - 7567 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:32:31.312 [INFO ] {CP } (-1) - 7568 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:32:31.694 [INFO ] {H323} (-1) - 7569 0 <<--[Msg]H323 Recv DTMF
2013-04-17T10:32:31.695 [INFO ] {CP } (-1) - 7570 0 -->>[Msg]DS30 Send (Call) DTMF
2013-04-17T10:32:33.715 [INFO ] {H323} (-1) - 7571 0 cH323MediaCtl recv GetCapabilities
2013-04-17T10:32:33.715 [INFO ] {H323} (-1) - 7572 0 cH323MediaCtl send AckCapabilities (1), m_bComplete=1
2013-04-17T10:32:33.716 [INFO ] {H323} (-1) - 7573 0 Transport IP Address=0.0.0.0:0
2013-04-17T10:32:33.716 [INFO ] {H323} (-1) - 7574 0 g711u(3/666)
2013-04-17T10:32:36.444 [INFO ] {H323} (-1) - 7575 0 cH323MediaCtl recv Disconnect
2013-04-17T10:32:36.444 [INFO ] {H323} (-1) - 7576 0 cH323InboundGuard from [Enabled] to [Disabled].
2013-04-17T10:32:36.445 [INFO ] {H323} (-1) - 7577 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundConnected
2013-04-17T10:32:36.446 [INFO ] {H323} (-1) - 7578 0 cH323MediaCtl recv DisableOutboundStream
2013-04-17T10:32:36.446 [INFO ] {H323} (-1) - 7579 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundConnected
2013-04-17T10:32:36.447 [INFO ] {H323} (-1) - 7580 0 cH323MediaCtl from [Active] to [WaitNegComplete].
2013-04-17T10:32:36.447 [INFO ] {H323} (-1) - 7581 0 cH323OutboundGuard from [Enabled] to [Disabling].
2013-04-17T10:32:36.448 [INFO ] {H323} (-1) - 7582 0 H245 send TCS(null)
2013-04-17T10:32:36.449 [INFO ] {H323} (-1) - 7583 0 cH323Capabilities from [Idle] to [W4NullCapsAck].
2013-04-17T10:32:36.478 [INFO ] {H323} (-1) - 7584 0 cH323MediaCtl recv StopInboundStream
2013-04-17T10:32:36.479 [INFO ] {H323} (-1) - 7585 0 cH323MediaCtl from [WaitNegComplete] to [WaitOBS_StopIBSPending].
2013-04-17T10:32:36.522 [INFO ] {H323} (-1) - 7586 0 H245 recv TCS ACK
2013-04-17T10:32:36.523 [INFO ] {H323} (-1) - 7587 0 cH323Capabilities from [W4NullCapsAck] to [Idle].
2013-04-17T10:32:36.523 [INFO ] {H323} (-1) - 7588 0 cH323OutboundGuard from [Disabling] to [W4Channel].
2013-04-17T10:32:36.524 [INFO ] {H323} (-1) - 7589 0 cH323LogChan from [OutboundConnected] to [OutboundDisabling].
2013-04-17T10:32:36.535 [INFO ] {H323} (-1) - 7590 0 <<--[Msg]H323 Recv CLC for handle 0x107a6c3c
2013-04-17T10:32:36.536 [INFO ] {H323} (-1) - 7591 0 cH323LogChan from [OutboundDisabling] to [OutboundW4AckWithdraw].
2013-04-17T10:32:36.537 [INFO ] {H323} (-1) - 7592 0 RV handle 0x107a6c3c closed - handle count is now 1
2013-04-17T10:32:36.539 [INFO ] {H323} (-1) - 7593 0 cH323MediaCtl from [WaitOBS_StopIBSPending] to [WaitInboundReady].
2013-04-17T10:32:36.541 [INFO ] {H323} (-1) - 7594 0 cH323LogChan from [InboundConnected] to [InboundW4Idle].
2013-04-17T10:32:36.541 [INFO ] {H323} (-1) - 7595 0 -->>[Msg]H323 Send CLC (cmChannelDrop) for handle 0x107a6aa4
2013-04-17T10:32:36.543 [INFO ] {H323} (-1) - 7596 0 cH323MediaCtl send WithdrawOutboundStream
2013-04-17T10:32:36.562 [INFO ] {H323} (-1) - 7597 0 cH323MediaCtl recv AckWithdrawOutboundStream
2013-04-17T10:32:36.562 [INFO ] {H323} (-1) - 7598 0 cH323LogChan from [OutboundW4AckWithdraw] to [OutboundDisabled].
2013-04-17T10:32:36.563 [INFO ] {H323} (-1) - 7599 0 cH323OutboundGuard from [W4Channel] to [Disabled].
2013-04-17T10:32:36.565 [INFO ] {H323} (-1) - 7600 0 cH323MediaCtl send AckDisableOutboundStream
2013-04-17T10:32:36.621 [INFO ] {H323} (-1) - 7601 0 <<--[Msg]H323 Recv CLC for handle 0x107a6aa4
2013-04-17T10:32:36.621 [INFO ] {H323} (-1) - 7602 0 cH323LogChan from [InboundW4Idle] to [InboundIdle].
2013-04-17T10:32:36.622 [INFO ] {H323} (-1) - 7603 0 RV handle 0x107a6aa4 closed - handle count is now 0
2013-04-17T10:32:36.623 [INFO ] {H323} (-1) - 7604 0 cH323MediaCtl from [WaitInboundReady] to [Active].
2013-04-17T10:32:36.623 [INFO ] {H323} (-1) - 7605 0 cH323MediaCtl send AckStopInboundStream
2013-04-17T10:32:36.625 [INFO ] {H323} (-1) - 7606 0 cH323MediaCtl recv Disconnected
2013-04-17T10:32:36.625 [INFO ] {H323} (-1) - 7607 0 cH323MediaCtl from [Active] to [Disconnected].
2013-04-17T10:32:36.626 [INFO ] {H323} (-1) - 7608 0 cH323MediaCtl recv Connect RxTx
2013-04-17T10:32:36.627 [INFO ] {H323} (-1) - 7609 0 cH323MediaCtl from [Disconnected] to [WaitNegComplete].
2013-04-17T10:32:36.627 [INFO ] {H323} (-1) - 7610 0 cH323InboundGuard from [Disabled] to [Enabled].
2013-04-17T10:32:36.628 [INFO ] {H323} (-1) - 7611 0 cH323MediaCtl recv StartInboundStream g711Ulaw64k, fpp=3, ta=10.20.20.49:51010,51011
2013-04-17T10:32:36.629 [INFO ] {H323} (-1) - 7612 0 cH323MediaCtl from [WaitNegComplete] to [WaitOBS_StartIBSPending].
2013-04-17T10:32:36.631 [INFO ] {H323} (-1) - 7613 0 cH323MediaCtl recv EnableOutboundStream
2013-04-17T10:32:36.632 [INFO ] {H323} (-1) - 7614 0 sending non-NULL caps to OBS
2013-04-17T10:32:36.633 [INFO ] {H323} (-1) - 7615 0 cH323OutboundGuard from [Disabled] to [Enabling].
2013-04-17T10:32:36.634 [INFO ] {H323} (-1) - 7616 0 H245 send TCS(g711u(3/6)) using DesiredFpp
2013-04-17T10:32:36.637 [INFO ] {H323} (-1) - 7617 0 H245 send MSDetermine(61)
2013-04-17T10:32:36.638 [INFO ] {H323} (-1) - 7618 0 cH323Capabilities from [Idle] to [Negotiating].
2013-04-17T10:32:36.709 [INFO ] {H323} (-1) - 7619 0 H245 recv TCS ACK
2013-04-17T10:32:36.713 [INFO ] {H323} (-1) - 7620 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:32:36.713 [INFO ] {H323} (-1) - 7621 0 cH323Capabilities from [Negotiating] to [Idle].
2013-04-17T10:32:36.714 [INFO ] {H323} (-1) - 7622 0 LastSent: g711u(3/6)
2013-04-17T10:32:36.714 [INFO ] {H323} (-1) - 7623 0 LastRecvd: g711u(3/666)
2013-04-17T10:32:36.715 [INFO ] {H323} (-1) - 7624 0 H245 negotiation succeeded
2013-04-17T10:32:36.715 [INFO ] {H323} (-1) - 7625 0 Selected capability: g711u(3/666)
2013-04-17T10:32:36.716 [INFO ] {H323} (-1) - 7626 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:32:36.717 [INFO ] {H323} (-1) - 7627 0 cH323OutboundGuard from [Enabling] to [Enabled].
2013-04-17T10:32:36.717 [INFO ] {H323} (-1) - 7628 0 cH323LogChan from [OutboundDisabled] to [OutboundIdle].
2013-04-17T10:32:36.718 [INFO ] {H323} (-1) - 7629 0 cH323MediaCtl from [WaitOBS_StartIBSPending] to [WaitInboundReady].
2013-04-17T10:32:36.718 [INFO ] {H323} (-1) - 7630 0 cH323LogChan from [InboundIdle] to [InboundConnecting].
2013-04-17T10:32:36.719 [INFO ] {H323} (-1) - 7631 0 RV handle 0x107a6dd4 opened - handle count is now 1
2013-04-17T10:32:36.720 [INFO ] {H323} (-1) - 7632 0 -->>[Msg]H323 Send OLC ip = 10.20.20.49 data:51010 ctrl:51011 for handle 0x107a6dd4
2013-04-17T10:32:36.721 [INFO ] {H323} (-1) - 7633 0 Set RTCP address ip = 10.20.20.49:51011 for handle 0x107a6dd4
2013-04-17T10:32:36.722 [INFO ] {H323} (-1) - 7634 0 -->>[Msg]H323 Send OLC g711Ulaw64k, fpp=3
2013-04-17T10:32:36.739 [INFO ] {H323} (-1) - 7635 0 H245 recv TCS(g711u(3/666))
2013-04-17T10:32:36.739 [INFO ] {H323} (-1) - 7636 0 H245 send TCS ACK
2013-04-17T10:32:36.742 [INFO ] {H323} (-1) - 7637 0 Filtered: g711u(3/666)
2013-04-17T10:32:36.742 [INFO ] {H323} (-1) - 7638 0 H245 send MSDetermine(59)
2013-04-17T10:32:36.744 [INFO ] {H323} (-1) - 7639 0 cH323Capabilities from [Idle] to [RecvdNewCaps].
2013-04-17T10:32:36.819 [INFO ] {H323} (-1) - 7640 0 H245 recv MasterSlaveStatus (master)
2013-04-17T10:32:36.819 [INFO ] {H323} (-1) - 7641 0 cH323Capabilities from [RecvdNewCaps] to [Idle].
2013-04-17T10:32:36.821 [INFO ] {H323} (-1) - 7642 0 LastSent: g711u(3/6)
2013-04-17T10:32:36.821 [INFO ] {H323} (-1) - 7643 0 LastRecvd: g711u(3/666)
2013-04-17T10:32:36.822 [INFO ] {H323} (-1) - 7644 0 H245 negotiation succeeded
2013-04-17T10:32:36.822 [INFO ] {H323} (-1) - 7645 0 Selected capability: g711u(3/666)
2013-04-17T10:32:36.823 [INFO ] {H323} (-1) - 7646 0 Reordered capabilities: g711u(3/666)
2013-04-17T10:32:36.825 [INFO ] {H323} (-1) - 7647 0 RV handle 0x107a6f6c opened - handle count is now 2
2013-04-17T10:32:36.826 [INFO ] {H323} (-1) - 7648 0 SetOurRTCP ip = 10.70.30.10:4001
2013-04-17T10:32:36.827 [INFO ] {H323} (-1) - 7649 0 <<--[Msg]H323 Recv OLC for handle 0x107a6f6c
2013-04-17T10:32:36.828 [INFO ] {H323} (-1) - 7650 0 cH323LogChan from [OutboundIdle] to [OutboundOffering].
2013-04-17T10:32:36.829 [INFO ] {H323} (-1) - 7651 0 ForwardCapabilities: epfCaps are complete and not renegotiating, not forwarding
2013-04-17T10:32:36.829 [INFO ] {H323} (-1) - 7652 0 OfferOutbound ip = 10.70.30.10 data:0 ctrl:4001
2013-04-17T10:32:36.830 [INFO ] {H323} (-1) - 7653 0 cH323MediaCtl send OfferOutboundStream g711Ulaw64k, fpp=2
2013-04-17T10:32:36.833 [INFO ] {H323} (-1) - 7654 0 SetOurRTCP ip = 10.1.50.20:16941
2013-04-17T10:32:36.833 [INFO ] {H323} (-1) - 7655 0 SetOurRTP ip = 10.1.50.20:16940
2013-04-17T10:32:36.834 [INFO ] {H323} (-1) - 7656 0 <<--[Msg]H323 Recv OLC ACK
2013-04-17T10:32:36.835 [INFO ] {H323} (-1) - 7657 0 cH323LogChan from [InboundConnecting] to [InboundConnected].
2013-04-17T10:32:36.835 [INFO ] {H323} (-1) - 7658 0 IB SlowStart channel: ip = 10.1.50.20 data:16940 ctrl:16941 for handle 0x107a6dd4
2013-04-17T10:32:36.836 [INFO ] {H323} (-1) - 7659 0 Recv OLC ACK: ip = 10.1.50.20 data:16940 ctrl:16941 for handle 0x107a6dd4
2013-04-17T10:32:36.836 [INFO ] {H323} (-1) - 7660 0 Media connected (Inbound); codec=0(g711Ulaw64k) fpp=3
2013-04-17T10:32:36.837 [INFO ] {H323} (-1) - 7661 0 ForwardCapabilities: epfCaps are complete and not renegotiating, not forwarding
2013-04-17T10:32:36.844 [INFO ] {H323} (-1) - 7662 0 cH323MediaCtl from [WaitInboundReady] to [Active].
2013-04-17T10:32:36.844 [INFO ] {H323} (-1) - 7663 0 cH323MediaCtl send AckStartInboundStream
2013-04-17T10:32:36.868 [INFO ] {H323} (-1) - 7664 0 cH323MediaCtl recv AckOfferOutboundStream ip = 10.20.20.49 data:51010 ctrl:51011
2013-04-17T10:32:36.868 [INFO ] {H323} (-1) - 7665 0 cH323LogChan from [OutboundOffering] to [OutboundAnswering].
2013-04-17T10:32:36.869 [INFO ] {H323} (-1) - 7666 0 Set RTP address ip = 10.20.20.49:51010 for handle 0x107a6f6c
2013-04-17T10:32:36.869 [INFO ] {H323} (-1) - 7667 0 Set RTCP address ip = 10.20.20.49:51011 for handle 0x107a6f6c
2013-04-17T10:32:36.871 [INFO ] {H323} (-1) - 7668 0 -->>[Msg]H323 Send OLC ACK (cmChannelAnswer) for handle 0x107a6f6c
2013-04-17T10:32:36.874 [INFO ] {H323} (-1) - 7669 0 Media connected (Outbound); codec=0(g711Ulaw64k) fpp=2
2013-04-17T10:32:36.874 [INFO ] {H323} (-1) - 7670 0 cH323LogChan from [OutboundAnswering] to [OutboundConnected].
2013-04-17T10:33:05.985 [INFO ] {H323} (-1) - 7671 0 <<--[Msg]H323 Recv CLC for handle 0x107a6f6c
2013-04-17T10:33:05.986 [INFO ] {H323} (-1) - 7672 0 cH323LogChan from [OutboundConnected] to [OutboundDisconnecting].
2013-04-17T10:33:05.986 [INFO ] {H323} (-1) - 7673 0 RV handle 0x107a6f6c closed - handle count is now 1
2013-04-17T10:33:05.987 [INFO ] {H323} (-1) - 7674 0 cH323MediaCtl send WithdrawOutboundStream
2013-04-17T10:33:05.996 [INFO ] {H323} (-1) - 7675 0 cH323MediaCtl recv AckWithdrawOutboundStream
2013-04-17T10:33:05.996 [INFO ] {H323} (-1) - 7676 0 cH323LogChan from [OutboundDisconnecting] to [OutboundIdle].
2013-04-17T10:33:06.065 [INFO ] {H323} (-1) - 7677 0 <<--[Msg]H323 Recv CLC for handle 0x107a6dd4
2013-04-17T10:33:06.065 [INFO ] {H323} (-1) - 7678 0 cH323LogChan from [InboundConnected] to [InboundW4Stop].
2013-04-17T10:33:06.066 [INFO ] {H323} (-1) - 7679 0 RV handle 0x107a6dd4 closed - handle count is now 0
2013-04-17T10:33:06.162 [INFO ] {H323} (-1) - 7680 0 cH323Call from [Active] to [FarRlsWaitingIdle]
2013-04-17T10:33:06.163 [INFO ] {H323} (-1) - 7681 0 cH323MediaCtl recv Release
2013-04-17T10:33:06.163 [INFO ] {H323} (-1) - 7682 0 cH323MediaCtl from [Active] to [Releasing].
2013-04-17T10:33:06.164 [INFO ] {H323} (-1) - 7683 0 cH323OutboundGuard from [Enabled] to [Releasing].
2013-04-17T10:33:06.164 [INFO ] {H323} (-1) - 7684 0 There was no release complete reason in the RELCOM UUIE
2013-04-17T10:33:06.165 [INFO ] {H323} (-1) - 7685 0 <<--[Msg]H323 Recv RELEASE [ reason is: cmReasonTypeUndefinedReason cause is: Normal call clearing ]
2013-04-17T10:33:06.165 [INFO ] {H323} (-1) - 7686 0 DS30 RELEASE cause [ Normal call clearing ]
2013-04-17T10:33:06.166 [INFO ] {H323} (-1) - 7687 0 cH323MediaCtl send NotifyDisconnect
2013-04-17T10:33:06.167 [INFO ] {H323} (-1) - 7688 0 cH323Call from [FarRlsWaitingIdle] to [FarRlsWaitingMediaDisconnected]
2013-04-17T10:33:06.169 [INFO ] {H323} (-1) - 7689 0 cH323MediaCtl recv Disconnect
2013-04-17T10:33:06.170 [INFO ] {H323} (-1) - 7690 0 cH323MediaCtl recv DisableOutboundStream
2013-04-17T10:33:06.171 [INFO ] {H323} (-1) - 7691 0 cH323InboundChannel::StopFastStartChannel ignored in state InboundW4Stop
2013-04-17T10:33:06.171 [INFO ] {H323} (-1) - 7692 0 cH323LogChan from [OutboundIdle] to [OutboundDisabled].
2013-04-17T10:33:06.174 [INFO ] {H323} (-1) - 7693 0 cH323OutboundGuard from [Releasing] to [Dead].
2013-04-17T10:33:06.175 [INFO ] {H323} (-1) - 7694 0 cH323MediaCtl send AckDisableOutboundStream
2013-04-17T10:33:06.193 [INFO ] {H323} (-1) - 7695 0 cH323MediaCtl recv StopInboundStream
2013-04-17T10:33:06.194 [INFO ] {H323} (-1) - 7696 0 cH323LogChan from [InboundW4Stop] to [InboundIdle].
2013-04-17T10:33:06.195 [INFO ] {H323} (-1) - 7697 0 cH323MediaCtl send AckStopInboundStream
2013-04-17T10:33:06.196 [INFO ] {H323} (-1) - 7698 0 cH323MediaCtl recv Disconnected
2013-04-17T10:33:06.197 [INFO ] {H323} (-1) - 7699 0 cH323MediaCtl from [Releasing] to [Null].
2013-04-17T10:33:06.197 [INFO ] {CP } (-1) - 7700 0 Call from [Active] to [FarEndRlsPending Waiting PathGone].
2013-04-17T10:33:06.198 [INFO ] {H323} (-1) - 7701 0 calling cmCallClose m_hsCall=0x107de0bc
2013-04-17T10:33:06.203 [INFO ] {CP } (-1) - 7702 0 Call from [FarEndRlsPending Waiting PathGone] to [Waiting Release].
2013-04-17T10:33:06.203 [INFO ] {CP } (-1) - 7703 0 -->>[Msg]DS30 Send (Call) RELEASE
2013-04-17T10:33:06.217 [INFO ] {H323} (-1) - 7704 0 cH323MediaCtl from [Null] to [-Destroyed-].
2013-04-17T10:33:06.249 [INFO ] {CP } (-1) - 7705 0 Call from [Waiting Release] to [Null Incoming].
2013-04-17T10:33:06.250 [INFO ] {CP } (-1) - 7706 0 DS30terminal 0x108285d8 freed - count is now 0
2013-04-17T10:33:06.251 [INFO ] {CP } (-1) - 7707 0 ^===============================================^

 

[SupportDude]

Based on the logs it looks like your BCM IP is actually 10.25.20.15.
As you stated the connection to the Voicemail is fine (10.25.20.15), but the connection to the phone has no RTP in either direction.
The BCM IP Phone is at 10.20.20.49. I assume there is full connectivity between the Cisco and the 10.20.20.0 network and the 10.25.20.0 network.

Another possible problem happens after the Voicemail receives the DTMF.
The logs show the inbound and outbound streams tear down.
A renegotion happens to the new destination IP address of 10.20.20.49.
It appears both ends agree to use G711 with a 30ms payload size.
The inbound stream from the Cisco sets up using G711 30ms payload.
However, when the BCM phone tries to setup an outbound stream to the Cisco it use G711 with a 20ms payload size.
The codec mismatch could account for the speech path issue.

Try to make sure the IP phones are using the same codec and payload as the IP trunks on the BCM side.
The trunks appear to be using G711 at 30ms. Lock the phone down to G711 at 30ms.
Make sure VAD is the same on each side too.

What happens if you call the phone directly bypassing the voicemail?

What happens if after answering the BCM phone you place the call on hold and then pick it back up?

-SD-

http://www.mysupportguy.net

 

[twscrb]

@SupportDude

If I initiate the call from my Cisco IP phone to the BCM50 these are my Call Statistics from the Cisco phone:

Rcvr Codec: G.711u
Sender Codec: G.711u
Rcvr Size: 20 ms
Sender Size: 20 ms

This seems to indicate that the Cisco phone is matching the payload size from the BCM50.

Sender packets are constantly increasing but receiver packets never increase from 173.

If I call the phone directly bypassing the voicemail I see the same results.

 

[SupportDude]

That's interesting.
How are the BCM phones configured as far as Codec and payload size?

Did you try the on hold test?

-SD-

http://www.mysupportguy.net

 

[twscrb]

@SupportDude

How are the BCM phones configured as far as Codec and payload size?

From the BCM Element Manager if I go to: Resources - Telephone Resources - IP Trunks - H323 Media Parameters - the codec in the 'Selected List' is set to: G.711-uLaw and the G.711 payload size (ms) is 30.

I did the on hold test.
When I'm on the call with the BCM and they place me on hold, I don't hear anything; if I place them on hold they also don't hear anything.

However, if I make a normal (non-VoIP) call to the BCM, all on hold functions work as they should.