Troubleshooting the latest beta....
Hi all,
I've been having some troubles trying to establish a video connection between Xmeeting (latest beta, on a late model Macbook Pro running Leopard) and a Tandberg T150 application based endpoint via H.323.
The setup involves a routed gatekeeper in the middle (although the same issue occurs when dialling ip direct without a gatekeeper).
The call negotiation in the debug log appears to go just fine, and then things go to pot.
The user experience is that Audio connects, but there is no video from Xmeeting. The selfview of Xmeeting does show that the iSight camera is engaged, and I can see myself. Another strange thing is that it APPEARS based on the logs that H.263 is negotiated, but then XMOpalManager uses a H.261 stream.... definitely very strange. Given the success that other people are having, I must be doing something wrong...
The call logs looks like this:
2009-01-20 14:47:12 Calling host "13077228588" using H.323
2009-01-20 14:47:16 Call with "R. Chan (Office) [66.129.176.209]" established.
Local IP Address: 11.1.1.233 (Ethernet).
Remote Address: 13077228588 <at>
Remote Application: "Tandberg, 50".
2009-01-20 14:47:16 Media stream opened: sending "G.711-uLaw-64k"
2009-01-20 14:47:16 Media stream opened: sending "H.261 (CIF)"
2009-01-20 14:47:16 Media stream opened: receiving "G.711-uLaw-64k"
2009-01-20 14:47:25 Call with "R. Chan (Office) [66.129.176.209]" cleared.
Duration: 0:09
Call End Reason: User cleared call
2009-01-20 14:47:26 Media stream closed: "(null)" (Outgoing)
2009-01-20 14:47:26 Media stream closed: "(null)" (Outgoing)
2009-01-20 14:47:26 Media stream closed: "(null)" (Incoming)
2009-01-20 14:47:26 Media stream closed: "(null)" (Incoming)
The actual debug log that looks good (towards the end of the negotiation) looks like this:
24:45.820 H.245 Hand...0xb0a03000 patch.cxx(331) Patch Created Sink: format=XM-H.263-1996
24:45.820 H.245 Hand...0xb0a03000 patch.cxx(170) Patch AddSink
Source format:
Format Name = XM-H.263-1996
Media Type = video
Payload Type = H263
Encoding Name = H263
CIF MPI (R/W) = 1 FMTP name: CIF (0) UnsignedInt
CIF16 MPI (R/W) = 0 FMTP name: CIF16 (0) UnsignedInt
CIF4 MPI (R/W) = 0 FMTP name: CIF4 (0) UnsignedInt
Clock Rate (R/O) = 90000 UnsignedInt
Frame Height (R/W) = 288 UnsignedInt
Frame Time (R/W) = 3003 UnsignedInt
Frame Width (R/W) = 352 UnsignedInt
Is RFC 2429 (R/W) = 0 Boolean
Max Bit Rate (R/W) = 320000 UnsignedInt
Max Rx Frame Height (R/W) = 288 UnsignedInt
Max Rx Frame Width (R/W) = 352 UnsignedInt
Media Packetization (R/W) = "" String
Min Rx Frame Height (R/W) = 96 UnsignedInt
Min Rx Frame Width (R/W) = 128 UnsignedInt
QCIF MPI (R/W) = 1 FMTP name: QCIF (0) UnsignedInt
Rate Control Enable (R/W) = 0 Boolean
Rate Control Max Frames Skip (R/W) = 5 UnsignedInt
Rate Control Window Size (R/W) = 5000 UnsignedInt
SQCIF MPI (R/W) = 1 FMTP name: SQCIF (0) UnsignedInt
Target Bit Rate (R/W) = 320000 UnsignedInt
Destination format:
Format Name = XM-H.263-1996
Media Type = video
Payload Type = H263
Encoding Name = H263
CIF MPI (R/W) = 1 FMTP name: CIF (0) UnsignedInt
CIF16 MPI (R/W) = 0 FMTP name: CIF16 (0) UnsignedInt
CIF4 MPI (R/W) = 0 FMTP name: CIF4 (0) UnsignedInt
Clock Rate (R/O) = 90000 UnsignedInt
Frame Height (R/W) = 288 UnsignedInt
Frame Time (R/W) = 3003 UnsignedInt
Frame Width (R/W) = 352 UnsignedInt
Is RFC 2429 (R/W) = 0 Boolean
Max Bit Rate (R/W) = 320000 UnsignedInt
Max Rx Frame Height (R/W) = 288 UnsignedInt
Max Rx Frame Width (R/W) = 352 UnsignedInt
Media Packetization (R/W) = "" String
Min Rx Frame Height (R/W) = 96 UnsignedInt
Min Rx Frame Width (R/W) = 128 UnsignedInt
QCIF MPI (R/W) = 1 FMTP name: QCIF (0) UnsignedInt
Rate Control Enable (R/W) = 0 Boolean
Rate Control Max Frames Skip (R/W) = 5 UnsignedInt
Rate Control Window Size (R/W) = 5000 UnsignedInt
SQCIF MPI (R/W) = 1 FMTP name: SQCIF (0) UnsignedInt
Target Bit Rate (R/W) = 320000 UnsignedInt
24:45.820 H.245 Hand...0xb0a03000 patch.cxx(173) Patch Added direct media stream sink XMMediaStream-Sink-XM-H.263-1996
24:45.820 H.245 Hand...0xb0a03000 connection.cxx(709) OpalCon Sink stream of connection Call[m979231041]-EP<xm>[1] uses patch Patch OpalRTPMediaStream-Source-XM-H.263-1996 -> XMMediaStream-Sink-XM-H.263-1996
24:45.820 H.245 Hand...0xb0a03000 connection.cxx(709) OpalCon Source stream of connection Call[m979231041]-EP<h323>[localhost/13508] uses patch Patch OpalRTPMediaStream-Source-XM-H.263-1996 -> XMMediaStream-Sink-XM-H.263-1996
24:45.820 H.245 Hand...0xb0a03000 h323ep.cxx(1081) H323 Started receiving logical channel: XM-H.263-1996 <3>
24:45.821 H.245 Hand...0xb0a03000 osutil.cxx(188) PWLib File handle high water mark set: 114 Thread unblock pipe
24:45.821 H.245 Hand...0xb0a03000 tlibthrd.cxx(330) PWLib Created thread 0x1a92bb10 Media Patch
24:45.821 H.245 Hand...0xb0a03000 tlibthrd.cxx(423) PWLib Thread high water mark set: 13
24:45.821 H.245 Hand...0xb0a03000 tlibthrd.cxx(427) set thread to have the highest priority (MACOSX)
24:45.821 H.245 Hand...0xb0a03000 tlibthrd.cxx(634) relativePriority is 15 base priority is 47
24:45.821 H.245 Hand...0xb0a03000 patch.cxx(109) Media Starting thread Media Patch:0xb0e21000
24:45.821 Media Patch:0xb0e21000 tlibthrd.cxx(834) PWLib Started thread 0x1a92bb10 Media Patch:0xb0e21000
24:45.821 H.245 Hand...0xb0a03000 h323pdu.cxx(80) H245 Sending PDU:
response openLogicalChannelAck {
forwardLogicalChannelNumber = 2
forwardMultiplexAckParameters = h2250LogicalChannelAckParameters {
sessionID = 2
mediaChannel = unicastAddress iPAddress {
network = 4 octets {
0b 01 01 e9 ....
}
tsapIdentifier = 5004
}
mediaControlChannel = unicastAddress iPAddress {
network = 4 octets {
0b 01 01 e9 ....
}
tsapIdentifier = 5005
}
flowControlToZero = false
}
}
24:45.821 H.245 Hand...0xb0a03000 h323.cxx(3509) H323 InternalEstablishedConnectionCheck: connectionState=EstablishedConnection fastStartState=FastStartDisabled H.245 is ready
And then this starts happening - I don't understand:
1) why the "Operation not permitted" occurs
2) why Xmeeting starts to send H.261 after negotiating H.263
3) what the writeframe failures are.
I suspect the jitter buffer is exceeded due to the additional time/load of the debugging turned on.
24:45.821 H.245 Hand...0xb0a03000 h323.cxx(3509) H323 InternalEstablishedConnectionCheck: connectionState=EstablishedConnection fastStartState=FastStartDisabled H.245 is ready
24:45.908 Media Patch:0xb0b07000 jitter.cxx(524) RTP Jitter buffer length exceeded
24:45.908 Media Patch:0xb0b07000 jitter.cxx(533) RTP Jitter buffer length exceed was prior to first write. Not increasing buffer size
24:45.910 PExternalT...0xa0559720 XMOpalManager.cpp(692) 2009-01-20 14:41:48 Call with "R. Chan (Office) [66.129.176.209]" established.
Local IP Address: 11.1.1.233 (Ethernet).
Remote Address: 13077228588 <at>
Remote Application: "Tandberg, 50".
24:45.912 H.245 Hand...0xb0a03000 h323.cxx(2640) H245 Received TPKT: size=9 pos=0.0 {
70 e0 06 00 00 01 20 0c 80 p
}
24:45.912 H.245 Hand...0xb0a03000 h323pdu.cxx(80) H245 Receiving PDU:
indication flowControlIndication {
scope = logicalChannelNumber 2
restriction = maximumBitRate 3200
}
24:45.912 H.245 Hand...0xb0a03000 h323.cxx(3509) H323 InternalEstablishedConnectionCheck: connectionState=EstablishedConnection fastStartState=FastStartDisabled H.245 is ready
24:45.926 PExternalT...0xa0559720 XMOpalManager.cpp(692) 2009-01-20 14:41:48 Media stream opened: sending "G.711-uLaw-64k"
24:45.927 PExternalT...0xa0559720 XMOpalManager.cpp(692) 2009-01-20 14:41:48 Media stream opened: sending "H.261 (CIF)"
24:45.927 PExternalT...0xa0559720 XMOpalManager.cpp(692) 2009-01-20 14:41:48 Media stream opened: receiving "G.711-uLaw-64k"
24:46.268 Media Patch:0xb0b07000 jitter.cxx(492) RTP Jitter buffer target realigned to current jitter buffer
24:46.326 Media Patch:0xb0b07000 jitter.cxx(492) RTP Jitter buffer target realigned to current jitter buffer
24:46.545 XMeeting rtpconn.cxx(519) RTP Found existing RTP session 1
24:46.545 XMeeting rtpconn.cxx(519) RTP Found existing RTP session 2
24:46.771 PExternalT...0xb02b2000 osutils.cxx(90) PTLib Created external thread 0x1a89b4a0 for id 0xb02b2000
24:46.771 PExternalT...0xb02b2000 rtp.cxx(816) RTP Session 2, first sent data: ver=2 pt=H261 psz=1378 m=0 x=0 seq=44128 ts=4211682454 src=65deb377 ccnt=0
24:46.771 PExternalT...0xb02b2000 rtp.cxx(2115) RTP_UDP Session 2, write error on data port (1): Operation not permitted
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
24:46.772 PExternalT...0xb02b2000 patch.cxx(496) Patch WriteFrame failed
Can someone point out where I'm going wrong?
Thanks,
Russ
------------------------------------------------------------------------------
This SF.net email is sponsored by:
SourcForge Community
SourceForge wants to tell your story.
http://p.sf.net/sfu/sf-spreadtheword
------------------------------------------------------------------------------
This SF.net email is sponsored by:
SourcForge Community
SourceForge wants to tell your story.
http://p.sf.net/sfu/sf-spreadtheword
RSS Feed