Problem with H264RtpPacketizer

[dgblack]

Problem with H264RtpPacketizer

[dgblack]

Update: weirdly, this new error is solved by switching the order of the depacketizer and the RTCP receiving session back to what it was:

videoReceivingSession = std::make_shared<rtc::H264RtpDepacketizer>(rtc::H264RtpDepacketizer::Separator::LongStartSequence);
videoReceivingSession->addToChain(std::make_shared<rtc::RtcpReceivingSession>());

Thanks for the help!

[paullouisageneau]

Ah yes my bad, order was right. The pipeline is run from first to last for sending and from last to first for receiving, which allows you to setup a bidirectional track.

I didn't realise one has to manually update the timestamp of the MediaHandler's rtpConfig before sending every frame (seems like this could be done internally?).

In a typical setup you should put the frame capture timestamp instead of the current time here, that's why it's not automated. It's quite cumbersome to set the timestamp in the config so I think I'll add it as metadata on the send() method.

[paullouisageneau]

RtcpSrReporter and RtcpNackResponder are useless on receiving-only side, you should remove them.

The chain order matters, RtcpReceivingSession can't operate after depacketization as it expects RTP/RTCP input (There must be warnings in the log). You need to create the RtcpReceivingSession first, then add the H264RtpDepacketizer.

[dgblack]

Thank you so much for the quick response! I removed the RtcpSrReporter and RtcpNackResponder on the receiving side. I had actually already tried switching the order of the RtcpReceivingSession and H264RtpDepacketizer because it seemed to make more sense. The order I wrote here was based on this which was linked in #676 . Unfortunately, I still have the same issue, though, either way.

There are no warnings or errors or relevant debug messages in the logs as far as I can see:

2024-06-06 08:30:47.121 DEBUG [55358] [rtc::impl::Init::doInit@113] Global initialization
2024-06-06 08:30:47.121 DEBUG [55358] [rtc::impl::Init::doInit@123] Spawning 16 threads
2024-06-06 08:30:47.122 DEBUG [55429] [rtc::impl::PollService::runLoop@164] Poll service started
2024-06-06 08:30:47.128 DEBUG [55358] [rtc::impl::TcpTransport::TcpTransport@57] Initializing TCP transport
2024-06-06 08:30:47.128 DEBUG [55358] [rtc::impl::TcpTransport::connect@150] Connecting to [removed ip]
2024-06-06 08:30:47.129 DEBUG [55416] [rtc::impl::TcpTransport::resolve@164] Resolving [removed ip]
2024-06-06 08:30:47.129 DEBUG [55416] [rtc::impl::TcpTransport::createSocket@277] Trying address [removed ip]
2024-06-06 08:30:47.129 DEBUG [55415] [rtc::impl::Certificate::Generate@430] Generating certificate (OpenSSL)
2024-06-06 08:30:47.131 INFO  [55429] [rtc::impl::TcpTransport::attempt@256] TCP connected
2024-06-06 08:30:47.131 DEBUG [55429] [rtc::impl::WsTransport::WsTransport@61] Initializing WebSocket transport
2024-06-06 08:30:47.131 DEBUG [55429] [rtc::impl::WsTransport::sendHttpRequest@201] Sending WebSocket HTTP request
2024-06-06 08:30:47.136 DEBUG [55429] [rtc::impl::WsHandshake::parseHttpResponse@205] WebSocket response code=101
2024-06-06 08:30:47.136 INFO  [55429] [rtc::impl::WsTransport::incoming@129] WebSocket client-side open
2024-06-06 08:30:47.137 DEBUG [55429] [rtc::impl::WebSocket::initWsTransport@434] WebSocket open
2024-06-06 08:30:47.137 DEBUG [55429] [rtc::impl::WsTransport::sendFrame@375] WebSocket sending frame: opcode=1, length=49
2024-06-06 08:30:47.141 DEBUG [55429] [rtc::impl::WsTransport::recvFrame@302] WebSocket received frame: opcode=1, length=8
2024-06-06 08:30:47.141 DEBUG [55429] [rtc::impl::WsTransport::recvFrame@323] WebSocket finished message: type=text, size=8
2024-06-06 08:30:47.141 DEBUG [55429] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice)
2024-06-06 08:30:47.141 INFO  [55429] [rtc::impl::IceTransport::IceTransport@113] Using STUN server "stun.l.google.com:19302"
2024-06-06 08:30:47.141 DEBUG [55429] [rtc::impl::PeerConnection::processLocalDescription@1000] Adding media to local description, mid="vid", removed=false
2024-06-06 08:30:47.141 DEBUG [55429] [rtc::impl::PeerConnection::processLocalDescription@1020] Adding application to local description, mid="0"
2024-06-06 08:30:47.141 INFO  [55429] [rtc::impl::PeerConnection::changeSignalingState@1290] Changed signaling state to have-local-offer
2024-06-06 08:30:47.141 INFO  [55429] [rtc::impl::PeerConnection::changeGatheringState@1277] Changed gathering state to in-progress
2024-06-06 08:30:47.142 INFO  [55429] [rtc::impl::IceTransport::LogCallback@379] juice: Changing state to gathering
2024-06-06 08:30:47.142 INFO  [55429] [rtc::impl::IceTransport::LogCallback@379] juice: Changing state to connecting
2024-06-06 08:30:47.142 INFO  [55429] [rtc::impl::PeerConnection::changeIceState@1259] Changed ICE state to checking
2024-06-06 08:30:47.142 INFO  [55429] [rtc::impl::PeerConnection::changeState@1241] Changed state to connecting
2024-06-06 08:30:47.155 INFO  [55435] [rtc::impl::IceTransport::LogCallback@379] juice: Using STUN server stun.l.google.com:19302
[GL.ContextGLX] Direct GLX rendering context obtained (ContextGLX.cpp:354)
2024-06-06 08:30:47.167 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: STUN server binding successful
2024-06-06 08:30:47.167 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: Got STUN mapped address 2001:a61:258b:801:2109:44c2:f5a1:d20:43965 from server
2024-06-06 08:30:47.217 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: STUN server binding successful
2024-06-06 08:30:47.217 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: Got STUN mapped address 93.104.74.195:43965 from server
2024-06-06 08:30:47.217 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: Candidate gathering done
2024-06-06 08:30:47.217 INFO  [55434] [rtc::impl::PeerConnection::changeGatheringState@1277] Changed gathering state to complete
2024-06-06 08:30:47.218 DEBUG [55425] [rtc::impl::WsTransport::sendFrame@375] WebSocket sending frame: opcode=1, length=1299
2024-06-06 08:30:47.513 DEBUG [55429] [rtc::impl::WsTransport::recvFrame@302] WebSocket received frame: opcode=1, length=1344
2024-06-06 08:30:47.513 DEBUG [55429] [rtc::impl::WsTransport::recvFrame@323] WebSocket finished message: type=text, size=1344
2024-06-06 08:30:47.513 INFO  [55429] [rtc::impl::IceTransport::LogCallback@379] juice: Connectivity timer started
2024-06-06 08:30:47.513 INFO  [55429] [rtc::impl::PeerConnection::changeSignalingState@1290] Changed signaling state to stable
2024-06-06 08:30:47.515 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: Changing state to connected
2024-06-06 08:30:47.515 INFO  [55434] [rtc::impl::PeerConnection::changeIceState@1259] Changed ICE state to connected
2024-06-06 08:30:47.515 INFO  [55434] [rtc::impl::PeerConnection::initDtlsTransport@276] This connection requires media support
2024-06-06 08:30:47.515 DEBUG [55434] [rtc::impl::DtlsTransport::DtlsTransport@733] Initializing DTLS transport (OpenSSL)
2024-06-06 08:30:47.515 DEBUG [55434] [rtc::impl::DtlsSrtpTransport::DtlsSrtpTransport@69] Initializing DTLS-SRTP transport
2024-06-06 08:30:47.515 DEBUG [55434] [rtc::impl::DtlsTransport::start@836] Starting DTLS transport
2024-06-06 08:30:48.271 INFO  [55417] [rtc::impl::DtlsTransport::doRecv@959] DTLS handshake finished
2024-06-06 08:30:48.271 INFO  [55417] [rtc::impl::DtlsSrtpTransport::postHandshake@303] Deriving SRTP keying material (OpenSSL)
2024-06-06 08:30:48.271 DEBUG [55417] [rtc::impl::DtlsSrtpTransport::postHandshake@309] SRTP profile is: SRTP_AEAD_AES_256_GCM
2024-06-06 08:30:48.271 DEBUG [55417] [rtc::impl::SctpTransport::SctpTransport@162] Initializing SCTP transport
2024-06-06 08:30:48.271 DEBUG [55417] [rtc::impl::SctpTransport::connect@352] SCTP connecting (local port=5000, remote port=5000)
mmt: RTC track with label vid opened
2024-06-06 08:30:48.278 DEBUG [55423] [rtc::impl::SctpTransport::processNotification@865] SCTP negotiated streams: incoming=1024, outgoing=1024
2024-06-06 08:30:48.278 INFO  [55423] [rtc::impl::SctpTransport::processNotification@870] SCTP connected
2024-06-06 08:30:48.278 INFO  [55423] [rtc::impl::PeerConnection::changeState@1241] Changed state to connected
2024-06-06 08:30:48.278 DEBUG [55423] [rtc::impl::PeerConnection::assignDataChannels@724] Assigning stream 1 to DataChannel
mmt: RTC DataChannel from peer with label franka opened
2024-06-06 08:30:49.768 INFO  [55434] [rtc::impl::IceTransport::LogCallback@379] juice: Changing state to completed
2024-06-06 08:30:49.768 INFO  [55434] [rtc::impl::PeerConnection::changeIceState@1259] Changed ICE state to completed

[dgblack]

Ok, I found the issue. I didn't realise one has to manually update the timestamp of the MediaHandler's rtpConfig before sending every frame (seems like this could be done internally?). I added the following before sending frames:

uint64_t elapsed = currentMillisecondsSinceEpochUtc() - startTimestampMs;
uint32_t elapsedTimestamp = videoSendingSession->rtpConfig->secondsToTimestamp(((double)elapsed)/1000.0);
videoSendingSession->rtpConfig->timestamp = videoSendingSession->rtpConfig->startTimestamp + elapsedTimestamp;

Note, currentMillisecondsSinceEpochUtc is a custom function and startTimestampMs is created when the connection starts, before the first packet. The packets are now received and I get this:

2024-06-06 15:06:11.328 WARN  [81996] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 30 (over 1 seconds)
2024-06-06 15:06:11.528 INFO  [82004] [rtc::impl::IceTransport::LogCallback@379] juice: Changing state to completed
2024-06-06 15:06:11.528 INFO  [82004] [rtc::impl::PeerConnection::changeIceState@1259] Changed ICE state to completed
2024-06-06 15:06:12.335 WARN  [81983] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 31 (over 1 seconds)
2024-06-06 15:06:13.359 WARN  [81998] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 30 (over 1 seconds)
2024-06-06 15:06:14.366 WARN  [81998] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 31 (over 1 seconds)
2024-06-06 15:06:15.393 WARN  [81998] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 30 (over 1 seconds)
2024-06-06 15:06:16.401 WARN  [81986] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 31 (over 1 seconds)
2024-06-06 15:06:17.422 WARN  [81993] [rtc::impl::LogCounter::operator++@29] Number of malformed RTP headers: 30 (over 1 seconds)
2024-06-06 15:06:17.964 ERROR [81985] [rtc::impl::DtlsTransport::doRecv@987] DTLS recv: Unknown H264 RTP Packetization
2024-06-06 15:06:17.964 INFO  [81985] [rtc::impl::DtlsTransport::doRecv@991] DTLS closed
2024-06-06 15:06:17.964 INFO  [81985] [rtc::impl::PeerConnection::changeState@1241] Changed state to disconnected
2024-06-06 15:06:17.965 INFO  [81985] [rtc::impl::SctpTransport::incoming@454] SCTP disconnected