AirenSoft / OvenMediaEngine

OvenMediaEngine (OME) is a Sub-Second Latency Live Streaming Server with Large-Scale and High-Definition. #WebRTC #LLHLS
https://airensoft.com/ome.html
GNU Affero General Public License v3.0
2.61k stars 1.06k forks source link

RTCP Sender Report RTP Timestamp Rollover Issue #1388

Closed the-real-rusty-shackleford closed 1 year ago

the-real-rusty-shackleford commented 1 year ago

Describe the bug When an RTCP sender report is used to adjust timestamps from an RTSP stream, the lip sync clock's pts does not appear to be calculated correctly. When the RTP timestamp, which is an unsigned 32-bit integer, rolls over, the PTS jumps by close to UINT32MAX.

The relevant code is here: https://github.com/AirenSoft/OvenMediaEngine/blob/master/src/projects/base/ovlibrary/lip_sync_clock.cpp#L80

auto pts = clock->_pts + ((int64_t)clock->_extended_rtp_timestamp - (int64_t)clock->_rtcp_timestamp);

When clock->_rtcp_timestamp rolls over to 0, nothing is being subtracted, which results in a large jump.

This ultimately caused an issue when using the HLS dump feature. The PTS jumps by nearly UINT32MAX, which is 13.25 hours when the time base is 1/90000. This causes the HLS chunklist to become corrupted with a large jump in the timestamps. See the snippit below.

From chunklist_0_video_bad_llhls.m3u8:

#EXT-X-PROGRAM-DATE-TIME:2023-09-19T09:30:11.780+00:00
#EXTINF:47727.863189,
seg_0_3588_video_bad_llhls.m4s
#EXT-X-PROGRAM-DATE-TIME:2023-09-19T22:45:39.643+00:00

I have seen the issue with three different brands of IP cameras (AXIS, Digital Watchdog, and Hanwa). I am not sure whether OME is handling this roll over incorrectly, or whether the cameras are not sending correct SR reports.

To Reproduce See code example below. If necessary I can provide more details on how to reproduce in OME. The basic idea is to connect to an IP camera's RTSP stream using RTPSPull, then start an HLS dump and let it run for 13.25 hours.

Expected behavior The calculated PTS should not jump.

Logs The jump occurs here.

[09-19 09:30:18.106] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219168993) final_pts(1938055453) last_rtp_timestamp(343909) rtp_timestamp(343909) delta(12000) extended_rtp_timestamp(4295311205)
[09-19 09:30:18.143] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:118  | Update SR : id(0) NTP(3840646879/2535921349) pts(345658219163139) timestamp(343909)
[09-19 09:30:18.289] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345662514142435) final_pts(6233028895) last_rtp_timestamp(355909) rtp_timestamp(355909) delta(12000) extended_rtp_timestamp(4295323205)

The more complete logs are below, which go all the way back to the previous SR. You can see that the SR's RTP timestamp has rolled over from 4294855205 to 343909, and with that, the calculated pts jumps from 1938055453 to 6233028895

[09-19 09:30:13.039] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218706748) final_pts(1937593208) last_rtp_timestamp(4294855205) rtp_timestamp(4294855205) delta(12000) extended_rtp_timestamp(4294855205)
[09-19 09:30:13.141] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:118  | Update SR : id(0) NTP(3840646874/2528967795) pts(345658218712993) timestamp(4294855205)
[09-19 09:30:13.169] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218724993) final_pts(1937611453) last_rtp_timestamp(4294867205) rtp_timestamp(4294867205) delta(12000) extended_rtp_timestamp(4294867205)
[09-19 09:30:13.305] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218736993) final_pts(1937623453) last_rtp_timestamp(4294879205) rtp_timestamp(4294879205) delta(12000) extended_rtp_timestamp(4294879205)
[09-19 09:30:13.439] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218748993) final_pts(1937635453) last_rtp_timestamp(4294891205) rtp_timestamp(4294891205) delta(12000) extended_rtp_timestamp(4294891205)
[09-19 09:30:13.569] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218760993) final_pts(1937647453) last_rtp_timestamp(4294903205) rtp_timestamp(4294903205) delta(12000) extended_rtp_timestamp(4294903205)
[09-19 09:30:13.705] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218772993) final_pts(1937659453) last_rtp_timestamp(4294915205) rtp_timestamp(4294915205) delta(12000) extended_rtp_timestamp(4294915205)
[09-19 09:30:13.840] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218784993) final_pts(1937671453) last_rtp_timestamp(4294927205) rtp_timestamp(4294927205) delta(12000) extended_rtp_timestamp(4294927205)
[09-19 09:30:13.970] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218796993) final_pts(1937683453) last_rtp_timestamp(4294939205) rtp_timestamp(4294939205) delta(12000) extended_rtp_timestamp(4294939205)
[09-19 09:30:14.106] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218808993) final_pts(1937695453) last_rtp_timestamp(4294951205) rtp_timestamp(4294951205) delta(12000) extended_rtp_timestamp(4294951205)
[09-19 09:30:14.288] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218820993) final_pts(1937707453) last_rtp_timestamp(4294963205) rtp_timestamp(4294963205) delta(12000) extended_rtp_timestamp(4294963205)
[09-19 09:30:14.373] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218832993) final_pts(1937719453) last_rtp_timestamp(7909) rtp_timestamp(7909) delta(12000) extended_rtp_timestamp(4294975205)
[09-19 09:30:14.504] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218844993) final_pts(1937731453) last_rtp_timestamp(19909) rtp_timestamp(19909) delta(12000) extended_rtp_timestamp(4294987205)
[09-19 09:30:14.638] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218856993) final_pts(1937743453) last_rtp_timestamp(31909) rtp_timestamp(31909) delta(12000) extended_rtp_timestamp(4294999205)
[09-19 09:30:14.773] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218868993) final_pts(1937755453) last_rtp_timestamp(43909) rtp_timestamp(43909) delta(12000) extended_rtp_timestamp(4295011205)
[09-19 09:30:14.905] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218880993) final_pts(1937767453) last_rtp_timestamp(55909) rtp_timestamp(55909) delta(12000) extended_rtp_timestamp(4295023205)
[09-19 09:30:15.039] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218892993) final_pts(1937779453) last_rtp_timestamp(67909) rtp_timestamp(67909) delta(12000) extended_rtp_timestamp(4295035205)
[09-19 09:30:15.170] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218904993) final_pts(1937791453) last_rtp_timestamp(79909) rtp_timestamp(79909) delta(12000) extended_rtp_timestamp(4295047205)
[09-19 09:30:15.305] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218916993) final_pts(1937803453) last_rtp_timestamp(91909) rtp_timestamp(91909) delta(12000) extended_rtp_timestamp(4295059205)
[09-19 09:30:15.440] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218928993) final_pts(1937815453) last_rtp_timestamp(103909) rtp_timestamp(103909) delta(12000) extended_rtp_timestamp(4295071205)
[09-19 09:30:15.570] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218940993) final_pts(1937827453) last_rtp_timestamp(115909) rtp_timestamp(115909) delta(12000) extended_rtp_timestamp(4295083205)
[09-19 09:30:15.705] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218952993) final_pts(1937839453) last_rtp_timestamp(127909) rtp_timestamp(127909) delta(12000) extended_rtp_timestamp(4295095205)
[09-19 09:30:15.840] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218964993) final_pts(1937851453) last_rtp_timestamp(139909) rtp_timestamp(139909) delta(12000) extended_rtp_timestamp(4295107205)
[09-19 09:30:15.971] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218976993) final_pts(1937863453) last_rtp_timestamp(151909) rtp_timestamp(151909) delta(12000) extended_rtp_timestamp(4295119205)
[09-19 09:30:16.106] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658218988993) final_pts(1937875453) last_rtp_timestamp(163909) rtp_timestamp(163909) delta(12000) extended_rtp_timestamp(4295131205)
[09-19 09:30:16.282] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219000993) final_pts(1937887453) last_rtp_timestamp(175909) rtp_timestamp(175909) delta(12000) extended_rtp_timestamp(4295143205)
[09-19 09:30:16.370] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219012993) final_pts(1937899453) last_rtp_timestamp(187909) rtp_timestamp(187909) delta(12000) extended_rtp_timestamp(4295155205)
[09-19 09:30:16.505] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219024993) final_pts(1937911453) last_rtp_timestamp(199909) rtp_timestamp(199909) delta(12000) extended_rtp_timestamp(4295167205)
[09-19 09:30:16.639] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219036993) final_pts(1937923453) last_rtp_timestamp(211909) rtp_timestamp(211909) delta(12000) extended_rtp_timestamp(4295179205)
[09-19 09:30:16.770] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219048993) final_pts(1937935453) last_rtp_timestamp(223909) rtp_timestamp(223909) delta(12000) extended_rtp_timestamp(4295191205)
[09-19 09:30:16.905] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219060993) final_pts(1937947453) last_rtp_timestamp(235909) rtp_timestamp(235909) delta(12000) extended_rtp_timestamp(4295203205)
[09-19 09:30:17.040] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219072993) final_pts(1937959453) last_rtp_timestamp(247909) rtp_timestamp(247909) delta(12000) extended_rtp_timestamp(4295215205)
[09-19 09:30:17.171] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219084993) final_pts(1937971453) last_rtp_timestamp(259909) rtp_timestamp(259909) delta(12000) extended_rtp_timestamp(4295227205)
[09-19 09:30:17.306] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219096993) final_pts(1937983453) last_rtp_timestamp(271909) rtp_timestamp(271909) delta(12000) extended_rtp_timestamp(4295239205)
[09-19 09:30:17.440] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219108993) final_pts(1937995453) last_rtp_timestamp(283909) rtp_timestamp(283909) delta(12000) extended_rtp_timestamp(4295251205)
[09-19 09:30:17.570] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219120993) final_pts(1938007453) last_rtp_timestamp(295909) rtp_timestamp(295909) delta(12000) extended_rtp_timestamp(4295263205)
[09-19 09:30:17.706] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219132993) final_pts(1938019453) last_rtp_timestamp(307909) rtp_timestamp(307909) delta(12000) extended_rtp_timestamp(4295275205)
[09-19 09:30:17.840] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219144993) final_pts(1938031453) last_rtp_timestamp(319909) rtp_timestamp(319909) delta(12000) extended_rtp_timestamp(4295287205)
[09-19 09:30:17.971] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219156993) final_pts(1938043453) last_rtp_timestamp(331909) rtp_timestamp(331909) delta(12000) extended_rtp_timestamp(4295299205)
[09-19 09:30:18.106] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219168993) final_pts(1938055453) last_rtp_timestamp(343909) rtp_timestamp(343909) delta(12000) extended_rtp_timestamp(4295311205)
[09-19 09:30:18.143] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:118  | Update SR : id(0) NTP(3840646879/2535921349) pts(345658219163139) timestamp(343909)
[09-19 09:30:18.289] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345662514142435) final_pts(6233028895) last_rtp_timestamp(355909) rtp_timestamp(355909) delta(12000) extended_rtp_timestamp(4295323205)

Server (please complete the following information):

Additional context The following C program demonstrates the issue.

#include <stdio.h>
#include <stdint.h>

void ClockTest_Before()
{
    // First log message is used to determine adjust_pts_us
    // [09-19 03:31:23.982] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345656281113540) final_pts(0) last_rtp_timestamp(2357263210) rtp_timestamp(2357263210) delta(0) extended_rtp_timestamp(2357263210)
    // [09-19 09:30:13.141] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:118  | Update SR : id(0) NTP(3840646874/2528967795) pts(345658218712993) timestamp(4294855205)
    // [09-19 09:30:18.106] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345658219168993) final_pts(1938055453) last_rtp_timestamp(343909) rtp_timestamp(343909) delta(12000) extended_rtp_timestamp(4295311205)

    double clock_timebase = 1.0 / 90000.0;
    uint64_t clock_extended_rtp_timestamp = 4295311205LL;                   // Calc PTS
    uint64_t clock_pts = 345658218712993LL;                                 // Update SR
    uint32_t clock_rtcp_timestamp = 4294855205;                             // Update SR
    uint64_t adjust_pts_us = 345656281113540LL * clock_timebase * 100000.0; // Calc PTS where final_pts == 0

    unsigned long long pts = clock_pts + ((int64_t)clock_extended_rtp_timestamp - (int64_t)clock_rtcp_timestamp);

    int64_t final_pts = pts - (int64_t)(adjust_pts_us / clock_timebase / 100000.0);

    printf("pts(%lld) final_pts(%lld)\n", pts, final_pts);
}

void ClockTest_After()
{
    // First log message is used to determine adjust_pts_us
    // [09-19 03:31:23.982] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345656281113540) final_pts(0) last_rtp_timestamp(2357263210) rtp_timestamp(2357263210) delta(0) extended_rtp_timestamp(2357263210)
    // [09-19 09:30:18.143] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:118  | Update SR : id(0) NTP(3840646879/2535921349) pts(345658219163139) timestamp(343909)
    // [09-19 09:30:18.289] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(345662514142435) final_pts(6233028895) last_rtp_timestamp(355909) rtp_timestamp(355909) delta(12000) extended_rtp_timestamp(4295323205)

    double clock_timebase = 1.0 / 90000.0;
    uint64_t clock_extended_rtp_timestamp = 4295323205LL;                   // Calc PTS
    uint64_t clock_pts = 345658219163139LL;                                 // Update SR
    uint32_t clock_rtcp_timestamp = 343909;                                 // Update SR
    uint64_t adjust_pts_us = 345656281113540LL * clock_timebase * 100000.0; // Calc PTS where final_pts == 0

    unsigned long long pts = clock_pts + ((int64_t)clock_extended_rtp_timestamp - (int64_t)clock_rtcp_timestamp);

    int64_t final_pts = pts - (int64_t)(adjust_pts_us / clock_timebase / 100000.0);

    printf("pts(%lld) final_pts(%lld)\n", pts, final_pts);
}

int main()
{
    printf("\nBefore\n\n");

    ClockTest_Before();

    printf("\n\nAfter\n\n");

    ClockTest_After();
}

Output:

Before

pts(345658219168993) final_pts(1938055453)

After

pts(345662514142435) final_pts(6233028895)
getroot commented 1 year ago

Thanks for the great report. I will look into this soon.

the-real-rusty-shackleford commented 1 year ago

I could be very wrong here, but could it be that the lip sync clock needs to keep track of the number of times the SR's RTP timestamp has wrapped around? Something like the below patch?

diff --git a/src/projects/base/ovlibrary/lip_sync_clock.cpp b/src/projects/base/ovlibrary/lip_sync_clock.cpp
index e07d94f2..b121eeb1 100644
--- a/src/projects/base/ovlibrary/lip_sync_clock.cpp
+++ b/src/projects/base/ovlibrary/lip_sync_clock.cpp
@@ -77,7 +77,7 @@ std::optional<uint64_t> LipSyncClock::CalcPTS(uint32_t id, uint32_t rtp_timestam

    std::shared_lock<std::shared_mutex> lock(clock->_clock_lock);
    // The timestamp difference can be negative.
-   auto pts = clock->_pts + ((int64_t)clock->_extended_rtp_timestamp - (int64_t)clock->_rtcp_timestamp);
+   auto pts = clock->_pts + ((int64_t)clock->_extended_rtp_timestamp - (int64_t)clock->_rtcp_timestamp - clock->_wraparound_count * std::numeric_limits<uint32_t>::max());

    // This is to make pts start at zero.
    if (_first_pts == true)
@@ -112,7 +112,19 @@ bool LipSyncClock::UpdateSenderReportTime(uint32_t id, uint32_t ntp_msw, uint32_

    std::lock_guard<std::shared_mutex> lock(clock->_clock_lock);
    clock->_updated = true;
+
+   if (rtcp_timestamp < clock->_rtcp_timestamp)
+   {
+       uint32_t delta = clock->_rtcp_timestamp - rtcp_timestamp;
+       if (delta > 0x80000000)
+       {
+           // wrap around
+           clock->_wraparound_count++;
+       }
+   }
+
    clock->_rtcp_timestamp = rtcp_timestamp;
+
    clock->_pts = ov::Converter::NtpTsToSeconds(ntp_msw, ntp_lsw) / clock->_timebase;

    logtd("Update SR : id(%u) NTP(%u/%u) pts(%lld) timestamp(%u)", id, ntp_msw, ntp_lsw, clock->_pts, clock->_rtcp_timestamp);
diff --git a/src/projects/base/ovlibrary/lip_sync_clock.h b/src/projects/base/ovlibrary/lip_sync_clock.h
index 2b229cef..721e734d 100644
--- a/src/projects/base/ovlibrary/lip_sync_clock.h
+++ b/src/projects/base/ovlibrary/lip_sync_clock.h
@@ -24,6 +24,7 @@ private:
        uint32_t    _last_rtp_timestamp = 0;
        uint64_t    _extended_rtp_timestamp = 0;
        uint64_t    _pts = 0;   // converted NTP timestamp to timebase timestamp
+       int64_t     _wraparound_count = 0;
    };

    // Id, Clock
getroot commented 1 year ago

Counting the wrap around count is also a good approach. But I modified it and committed it by updating delta for consistency with other code. Could you please confirm if this commit solves your problem? thank you

https://github.com/AirenSoft/OvenMediaEngine/commit/a1ba0f66e81a93b0a46bf5bc9b339295cef48358

the-real-rusty-shackleford commented 1 year ago

Thank you, I will run my tests and let you know.

the-real-rusty-shackleford commented 1 year ago

Looks good! Thank you for fixing this.

[10-02 19:04:39.409] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(351473604526817) final_pts(1211412884) last_rtp_timestamp(4294956813) rtp_timestamp(4294956813) delta(12000) extended_rtp_timestamp(4294956813)
[10-02 19:04:39.544] D [StreamMotor:52] LipSyncClock | lip_sync_clock.cpp:92   | Calc PTS : id(0) pts(351473604538817) final_pts(1211424884) last_rtp_timestamp(1517) rtp_timestamp(1517) delta(12000) extended_rtp_timestamp(4294968813)