C20 TC5.1.4 H323 call disconnects after 1h

epicolo · ‎10-23-2012

Hi, we have two C20 running TC5.1.4 registered on a VCS C X7.2 (actually there are more C20s, MCU, etc)

In a H323 point-to-point call, the call disconnects after 1h01m with reason "Temporary Failure/Adaptive Busy".

It is random (not alway disconnect). There is no FW in the path.

The same happen if the C20 calls the MCU (H323) and with other C20s also.

If the C20 call using SIP (ex: a Jabber/Movi client), the call don´t disconnect.

The VCS H323 parameters are all at default values.

Any idea?

Thanks

#At C20 log i found this:

Oct 23 11:32:07 arm2 video2: 5358627.99 DEC_FSM-1 I: intra request

Oct 23 11:32:07 arm2 video2: 5358628.53 DEC_FSM-1 I: intra request

Oct 23 13:32:07 (none) main: 5358629.07 MC I: RemoteParticipant::requestFastPictureUpdate(p=235,ch=2) inband

Oct 23 13:32:07 (none) main: 5358629.44 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close incoming media session (CLC/CLC-ACK, channel: 8)

Oct 23 13:32:07 (none) main: 5358629.45 MC I: RemoteParticipant::configureIncomingChannel: Capability table:

Oct 23 13:32:07 (none) main: 5358629.47 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close incoming media session (CLC/CLC-ACK, channel: 7)

Oct 23 13:32:07 (none) main: 5358629.47 MC I: RemoteParticipant::configureIncomingChannel: Capability table:

Oct 23 13:32:07 (none) main: 5358629.49 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close incoming media session (CLC/CLC-ACK, channel: 6)

Oct 23 13:32:07 (none) main: 5358629.50 MC I: RemoteParticipant::configureIncomingChannel: Capset empty

Oct 23 13:32:07 (none) main: 5358629.51 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close outgoing media session (CLC/CLC-ACK, channel: 1)

Oct 23 13:32:07 (none) main: 5358629.52 MC I: configureOutgoingChannel(p=235, ch=1): Configuring mode : iX (1): undefined 0k (modescontroller says real is: Audio (1): aud-off 0k )

Oct 23 13:32:07 (none) main: 5358629.53 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close outgoing media session (CLC/CLC-ACK, channel: 2)

Oct 23 13:32:07 (none) main: 5358629.54 MC I: configureOutgoingChannel(p=235, ch=2): Configuring mode : iX (2): undefined 0k (modescontroller says real is: Video (2): vid-off 0x0@0.0 0k )

Oct 23 13:32:08 (none) main: 5358629.56 H323Call I: h323_call_handler::handleH323RtpCloseSessionReq(p=235, s=1) Close outgoing media session (CLC/CLC-ACK, channel: 3)

Oct 23 13:32:08 (none) main: 5358629.57 MC I: configureOutgoingChannel(p=235, ch=4): Configuring mode : iX (4): undefined 0k (modescontroller says real is: Data (4): data-off 0k )

Oct 23 13:32:08 (none) main: 5358629.58 RTP !ER Rtp_Ready_doRTPSourceMuteReq(app=0,strm=1484) invalid remote RTCP address, suppressing report

Oct 23 13:32:08 (none) main: 5358629.58 RTP W: RtpRxMedia_processRtpPacket(sid=0, strm=1480) unable to find matching payload info, pt = 113, 1st consequtive packet

Oct 23 13:32:08 (none) main: 5358629.59 RTP !ER Rtp_Ready_doRTPSourceMuteReq(app=0,strm=1484) invalid remote RTCP address, suppressing report

Oct 23 13:32:08 (none) main: 5358629.59 RTP W: RtpRxMedia_processRtpPacket(sid=2, strm=1481) unable to find matching payload info, pt = 112, 1st consequtive packet

Oct 23 13:32:08 (none) main: 5358629.60 RTP I: RtpSession_FlowRateReq, (sid=0) rateInBitsPrSec = 704000, inited = 1, remoteFecSupport = 0, fecIsSupportedLocal=1

Oct 23 13:32:08 (none) main: 5358629.61 RTP I: RtpSession_FlowRateReq, (sid=2) rateInBitsPrSec = 704000, inited = 1, remoteFecSupport = 0, fecIsSupportedLocal=1

Oct 23 13:32:08 (none) main: 5358629.63 DATACTRL I: DataGateCfgReq(ig=227) hdlc=yes

Oct 23 13:32:08 (none) main: 5358630.14 H323Call I: h323_call::configureIncomingChannelCnf(p=235): Not sending openSessionCnf upon receive mode change

Oct 23 11:32:08 arm0 video0: Core h.264 v1 encoder destroyed, fullhd: 0

Oct 23 13:32:09 (none) main: 5358630.56 MC I: RemoteInputGateImpl::setIncomingModeReport(ig=2803,p=235) [Audio (1): aud-off stereo 0k ]

Oct 23 11:32:09 arm2 video2: Core h.264 v1 decoder destroyed

Oct 23 13:32:09 (none) main: 5358630.89 RTP W: RtpRxMedia_processRtpPacket(sid=0, strm=1480) unable to find matching payload info, pt = 113, 65st consequtive packet

Oct 23 13:32:10 (none) main: 5358631.56 RxDownspeed I: VideoInputGateImpl::updateDownspeed(ig=2806): reduce rate from 704000 to 624000 bit/s

Oct 23 13:32:10 (none) main: 5358631.64 RTP W: RtpRxMedia_processRtpPacket(sid=2, strm=1481) unable to find matching payload info, pt = 112, 65st consequtive packet

Oct 23 13:32:10 (none) main: 5358632.28 RTP W: RtpRxMedia_processRtpPacket(sid=0, strm=1480) unable to find matching payload info, pt = 113, 129st consequtive packet

Oct 23 13:32:10 (none) main: 5358632.36 H323Call I: h323_call_handler::handleDiscInd(p=235, s=1) Received disconnect indication (Cause: 11:55, h323 cause: 16:55)- RemoteRejected Q850

Oct 23 13:32:10 (none) main: 5358632.37 MC I: RemoteParticipant::reevalRefMode(p=235,ch=2) set ref [Video (2): vid-off 0x0@0.0 0k ] q= auto, t60=6000

Oct 23 13:32:10 (none) main: 5358632.38 ModesController I: ModesController::resetRateLimit(ch=2)

Oct 23 13:32:10 (none) main: 5358632.38 MC I: RemoteParticipant::modeChanged(p=235, ch=2): ModesController wants to run mode: Video (2): vid-off 0x0@0.0 0k

Oct 23 13:32:10 (none) main: 5358632.39 H323Call I: h323_call::sendOutgoingModesToStack(p=235): Modes sent to stack: audio: AAC-LD, video: vid-off, duo: vid-off, data: H.224-HDLC

Oct 23 13:32:10 (none) main: 5358632.49 H323Call I: h323_call::affirmIncomingDisconnect(p=235): Incoming disconnect affirmed

deamanga · ‎10-23-2012

Hi Elter,

For such of request, I will recommend you to open an SR to TAC to have a deeper analysis of the issue

BR

Dean.

epicolo · ‎10-23-2012

OK, opened.

I just put it here to see if someone had a similar experience.

tks

Danny De Ridder · ‎10-23-2012

Hello,

would this be related to congestion as noted in bold in http://www.javvin.com/protocol/H225v5.pdf.

Danny.

8.5 Procedures for maintaining QOS

=======================================

A number of methods exist for the H.323 gateway/terminal to respond to an increase in packet loss

or interarrival jitter in the far-end receiver. These methods can be grouped into those that are

appropriate for a rapid response to a short-term problem, such as a lost or delayed packet, and those

that are appropriate for a response to a longer-term problem such as growing congestion on the

packet-based network. Note that these methods do not seek to maintain the current quality of service,

but instead to provide for an orderly degradation of service. The following priorities shall be

observed such that, if present, media shall be degraded in the following order: Video, Data, Audio,

Control.

Short-term responses:

~~~~~~~~~~~~~~~~~~~~~~~~~

• reducing the frame rate for a short period of time: This may result in the H.323 gateway

sending additional H.261 fill frames in the packet-based network to SCN direction to

compensate for the packet under flow;

• reduce packet rate by switching to the optional mode where audio/video are mixed in one

packet (for further study);

• packet rate can also be reduced via the use of MB fragmentation of the video stream.

Longer-term responses:

~~~~~~~~~~~~~~~~~~~~~~~

• reducing media bit rate (e.g. switching from 384 kbit/s to 256 kbit/s): This may involve a

simple instruction to the encoder in a terminal, or it may involve the use of a rate reducer

function in the H.323 gateway. These changes are signalled via H.245 FlowControl

commands, or by logical channel signalling as appropriate;

• turning off media of lesser importance (e.g. turning off video to allow a large amount of

T.120 traffic);

• returning a busy signal (adaptive busy) to the receiver as an indication of packet-based

network congestion. This may be combined with turning off a media, or even all media other

than the control Transport Port. Adaptive busy is signalled via a Q.931 cause value in

Release Complete.

Rod.Blackie · ‎11-21-2012

Hi

Did you get an answer to your question?

I'm seeing simiar issues with my C20 running 5.1.4

C20 / VCS disconnect

Hi

We always seem to have problems calling VCS to VCS systems with endpoints via the internet. We're running 7.2 on our VCS and the remote company is running 7.1 on their VCS. Calls connect ok however there are random drops during the session 3 over a 1.5 hour session. I get user busy errors (logged on TMS) when trying to reconnect and I eventually get through after a couple of minutes trying. I've checked the C20 error logs and can find this error - can anyone explain the lines highlighed below? or explain why I'm getting the disconnects?

Thanks

Rod

(The VC call is passing over the internet to the remote system)

Nov 21 07:32:41 (none) main: 3150.48 MC I: RemoteParticipant::configureIncomingChannel: Capability table:

Nov 21 07:32:41 (none) main: 3150.48 H323Call I: h323_call_handler::handleH323IncMode: incoming mode

Nov 21 07:32:41 (none) main: 3150.48 MC I: RemoteParticipant::configureIncomingChannel: Capability table:

Nov 21 07:32:41 (none) main: 3150.48 H323Call I: h323_call::configureIncomingChannelCnf(p=6): Not sending openSessionCnf upon receive mode change

Nov 21 07:32:41 (none) main: 3150.49 DATACTRL I: DataGateCfgReq(ig=5) hdlc=yes

Nov 21 07:32:41 (none) main: 3150.49 H323Call I: h323_call::configureIncomingChannelCnf(p=6): Not sending openSessionCnf upon receive mode change

Nov 21 07:32:41 (none) main: 3150.49 H323Call I: h323_call_handler::handleH323IncMode: incoming mode

Nov 21 07:32:41 (none) main: 3150.50 MC I: RemoteParticipant::configureIncomingChannel: Capset empty

Nov 21 07:32:41 (none) main: 3150.50 H323Call I: h323_call_handler::handleH323IncMode: incoming mode

Nov 21 07:32:41 (none) main: 3150.50 MC I: RemoteParticipant::configureIncomingChannel: Capset empty

Nov 21 07:32:41 (none) main: 3150.50 H323Call I: h323_call::configureIncomingChannelCnf(p=6): Not sending openSessionCnf upon receive mode change

Nov 21 07:32:41 (none) main: 3150.74 MediaStreamController I: MV::getVCSetting getOutputPortStatus initialized 1

Nov 21 07:32:41 (none) main: 3150.74 MediaStreamController I: MV::getVCSetting localHwCookieHint_ 1 w 1920 h 1080

Nov 21 07:32:42 (none) main: 3150.79 VIDEOCTRL-0 I: Reset flux probe for (outputvideo,2)

Nov 21 07:32:42 (none) main: 3150.80 H323Call I: h323_call::configureIncomingChannelCnf(p=6): Not sending openSessionCnf upon receive mode change

Nov 21 07:32:42 (none) main: 3151.35 MC I: RemoteInputGateImpl::setIncomingModeReport(ig=60,p=6) [Audio (1): aud-off stereo 0k ]

Nov 21 07:32:44 (none) main: 3152.97 H323Call I: h323_call_handler::handleDiscInd(p=6, s=1) Received disconnect indication (Cause: 11:55, h323 cause: 16:55)- RemoteRejected Q850

Nov 21 07:32:44 (none) main: 3152.98 MC I: RemoteParticipant::reevalRefMode(p=6,ch=2) set ref [Video (2): vid-off 0x0@0.0 0k ] q= auto, t60=6000

Nov 21 07:32:44 (none) main: 3152.98 ModesController I: ModesController::resetRateLimit(ch=2)

Nov 21 07:32:44 (none) main: 3152.98 MC I: RemoteParticipant::modeChanged(p=6, ch=2): ModesController wants to run mode: Video (2): vid-off 0x0@0.0 0k

Nov 21 07:32:44 (none) main: 3152.99 H323Call I: h323_call::sendOutgoingModesToStack(p=6): Modes sent to stack: audio: AAC-LD, video: vid-off, duo: vid-off, data: H.224-HDLC

Nov 21 07:32:44 (none) main: 3153.03 H323Call I: h323_call::affirmIncomingDisconnect(p=6): Incoming disconnect affirmed

Nov 21 07:32:44 (none) main: 3153.09 MC W: RemoteParticipant::disconnectTokenParticipant(p=6) No call

Nov 21 07:32:44 (none) main: 3153.09 MC I: Conference::updateCommonCapSet(c=5)

Nov 21 07:32:44 (none) main: 3153.10 IXUser I: iXController teardownIxChannel: Not connected

Nov 21 07:32:44 (none) main: 3153.11 MC I: CapabilityControllerImpl::setCapset() reduced = 0, waitForDuoGate = 1, hasLegacyVideo = 0

Nov 21 07:32:44 (none) main: 3153.14 RTP I: TrafficCtrl: Deleting entry (main): id: 34, tcid: 65568

Nov 21 07:32:44 (none) main: 3153.14 RTP I: TrafficCtrl: Deleting entry (duo): id: 36, tcid: 65568

Nov 21 07:32:44 (none) main: 3153.15 CAMERA I: CamVisca::Ready_doCAMActionReq cameraId=1 actionId=20

Nov 21 07:32:44 (none) main: 3153.16 MediaStreamController I: MV::getVCSetting getOutputPortStatus initialized 1

Nov 21 07:32:44 (none) main: 3153.16 MediaStreamController I: MV::getVCSetting localHwCookieHint_ 1 w 1920 h 1080

Nov 21 07:32:44 (none) main: 3153.18 MediaStreamController I: doAUDIOMIXERREMGATECNF(ms-ig=7) not found

Nov 21 07:32:44 (none) main: 3153.19 DATACTRL I: DataGateRemReq(ig=5)

Nov 21 07:32:44 (none) main: 3153.20 DATACTRL I: DataGateRemReq(og=2)

epicolo · ‎11-21-2012

We opened a SR on TAC and after a lot of debugs they couldn´t found anything wrong with the devices but also there where no explanation for the behaviour.

We did a few large tcpdump and we could compare the VCS debug, C-Series debug and tcpdump. We observed that at an especific point an H245 RTT was sent from one side, received by the VCS, the VCS resent this H.245 RTT and the other device did not received this H.245 RTT. This other endpoint don´t respond (because it didn´t received) and the call drops.

After to explain this to the FW administrator, they researched inside the Firewall and changed one internal Timer regarding h245/H323. With this change, the calls don´t drop anymore.

(a was a FW between the VCS and one of the devices)

Regards

Rod.Blackie · ‎11-23-2012

Smashing Elter - thanks. I altered my H.323 (225 + 245) and SIP timeout settings on my Palo Alto firewall and it stopped the drop outs.

If anyone is interested the reason this happens is because:

(Courtesy of Rocketfire on vctalk)

Once a call has been established, the signaling session on TCP port 1720 goes idle even though there's a VC in session. This is normal behaviour.

Firewalls track individual sessions and will consider them dead after a short period of time if there's no traffic, typically 30 minutes for TCP. Firewalls don't give any indications to the endpoints that their session is now blocked. The endpoints could establish a new TCP session on port 1720, but they don't even know their old session is now longer working through the firewall.

The TCP drivers in the endpoints will send a keepalive every so often. How often depends on the TCP drivers and how the sessions was opened. I know HDX's used to wait two hours before sending a heartbeat!

Once the TCP driver in the codec fails to get a keep-alive acknowledgment, it will tear the session down, much to the surprise of the VC application. HDX's will drop back to their home screen without any error message when this happens. What other endpoints do is anyone guess. The clue is the repetitive timing of the failure, for example n x 30+13 minutes.

Ideally endpoints will send TCP keepalives more often than the firewall timeouts. But this is rarely a configurable item. Usually people just wind-up the timeouts on the firewall "to eleven", particularly for TCP:1729. The problem with this is not everyone else has done the same to their firewalls, so timeouts could still happen in calls with them.

Some firewalls will try to understand H.323 and make allowances for it, others will fudge up a TCP keepalive on behalf of an endpoint as a check before blocking the session. IMHO relying on firewall VC awareness isn't a good approach, as they are never fully VC aware.