WebRTC: Fixes to packet timing and loss statistics

lib/rtp.cpp

@@ -516,7 +516,7 @@ namespace RTP{
     }else{
       // packet is very early - assume dropped after PACKET_DROP_TIMEOUT packets
       while ((int16_t)(rtpSeq - pSNo) < -(int)PACKET_DROP_TIMEOUT){
-        WARN_MSG("Giving up on packet %u", rtpSeq);
+        VERYHIGH_MSG("Giving up on track %" PRIu64 " packet %u", packTrack, rtpSeq);
         ++rtpSeq;
         ++lostTotal;
         ++lostCurrent;
@@ -548,7 +548,7 @@ namespace RTP{
     }
     // packet is slightly early - buffer it
     if ((int16_t)(rtpSeq - pSNo) < 0){
-      HIGH_MSG("Buffering early packet #%u->%u", rtpSeq, pack.getSequence());
+      VERYHIGH_MSG("Buffering early packet #%u->%u", rtpSeq, pack.getSequence());
       packBuffer[pack.getSequence()] = pack;
     }
     // packet is late
@@ -616,7 +616,6 @@ namespace RTP{
     if (M.getCodec(tid) == "opus"){
       m = 48.0;
     }
-    bootMsOffset = M.getBootMsOffset();
     setProperties(M.getID(tid), M.getCodec(tid), M.getType(tid), M.getInit(tid), m);
   }
 
@@ -636,7 +635,7 @@ namespace RTP{
       if (rtpTime > 0x80000000lu){rtp64Time -= 0x100000000ll;}
     }
     uint64_t msTime = (rtp64Time - firstTime + 1 + 0x100000000ull * wrapArounds) / multiplier + milliSync;
-    int32_t rtpDiff = (bootMsOffset + msTime) - (Util::bootMS() - msDiff);
+    int32_t rtpDiff = msTime - (Util::bootMS() - msDiff);
     if (rtpDiff > 25 || rtpDiff < -25){
       INFO_MSG("RTP difference (%s %s): %" PRId32 "ms, syncing...", type.c_str(), codec.c_str(), rtpDiff);
       milliSync -= rtpDiff;
@@ -655,7 +654,7 @@ namespace RTP{
     // This part isn't codec-specific, so we do it before anything else.
     int64_t pTime = pkt.getTimeStamp();
     if (!firstTime){
-      milliSync = Util::bootMS() - bootMsOffset;
+      milliSync = Util::bootMS();
       firstTime = pTime + 1;
       INFO_MSG("RTP timestamp rollover expected in " PRETTY_PRINT_TIME,
                PRETTY_ARG_TIME((0xFFFFFFFFul - firstTime) / multiplier / 1000));

lib/rtp.h

@@ -149,7 +149,6 @@ namespace RTP{
 
   public:
     uint64_t trackId;
-    uint64_t bootMsOffset;
     double multiplier;    ///< Multiplier to convert from millis to RTP time
     std::string codec;    ///< Codec of this track
     std::string type;     ///< Type of this track
@@ -161,7 +160,7 @@ namespace RTP{
     bool recentWrap;      ///< True if a wraparound happened recently.
     uint32_t prevTime;
     uint64_t firstTime;
-    int32_t milliSync;
+    int64_t milliSync;
     void (*cbPack)(const DTSC::Packet &pkt);
     void (*cbInit)(const uint64_t track, const std::string &initData);
     // Codec-specific handlers

src/output/output_webrtc.cpp

@@ -50,11 +50,16 @@ namespace Mist{
   /* ------------------------------------------------ */
 
   OutWebRTC::OutWebRTC(Socket::Connection &myConn) : HTTPOutput(myConn){
+    totalPkts = 0;
+    totalLoss = 0;
+    totalRetrans = 0;
+    setPacketOffset = false;
+    packetOffset = 0;
     lastRecv = Util::bootMS();
     stats_jitter = 0;
     stats_nacknum = 0;
     stats_lossnum = 0;
-    stats_lossperc = 0;
+    stats_lossperc = 100.0;
     lastPackMs = 0;
     vidTrack = INVALID_TRACK_ID;
     prevVidTrack = INVALID_TRACK_ID;
@@ -65,7 +70,6 @@ namespace Mist{
     repeatInit = true;
 
     lastTimeSync = 0;
-    packetOffset = 0;
     maxSkipAhead = 0;
     needsLookAhead = 0;
     webRTCInputOutputThread = NULL;
@@ -994,6 +998,15 @@ namespace Mist{
     }
   }
 
+  void OutWebRTC::connStats(uint64_t now, Comms::Statistics &statComm){
+    statComm.setUp(myConn.dataUp());
+    statComm.setDown(myConn.dataDown());
+    statComm.setPacketCount(totalPkts);
+    statComm.setPacketLostCount(totalLoss);
+    statComm.setPacketRetransmitCount(totalRetrans);
+    statComm.setTime(now - myConn.connTime());
+  }
+
   // Checks if there is data on our UDP socket. The data can be
   // STUN, DTLS, SRTP or SRTCP. When we're receiving media from
   // the browser (e.g. from webcam) this function is called from
@@ -1022,6 +1035,33 @@ namespace Mist{
         FAIL_MSG("Unhandled WebRTC data. Type: %02X", fb);
       }
     }
+
+    //If this is an incoming push, handle receiver reports and keyframe interval
+    if (isPushing()){
+      uint64_t now = Util::bootMS();
+      
+      //Receiver reports and packet loss calculations
+      if (now >= rtcpTimeoutInMillis){
+        std::map<uint64_t, WebRTCTrack>::iterator it;
+        for (it = webrtcTracks.begin(); it != webrtcTracks.end(); ++it){
+          if (M.getType(it->first) != "video"){continue;}//Video-only, at least for now
+          sendRTCPFeedbackREMB(it->second);
+          sendRTCPFeedbackRR(it->second);
+        }
+        rtcpTimeoutInMillis = now + 1000; /* was 5000, lowered for FEC */
+      }
+
+      //Keyframe requests
+      if (now >= rtcpKeyFrameTimeoutInMillis){
+        std::map<uint64_t, WebRTCTrack>::iterator it;
+        for (it = webrtcTracks.begin(); it != webrtcTracks.end(); ++it){
+          if (M.getType(it->first) != "video"){continue;}//Video-only
+          sendRTCPFeedbackPLI(it->second);
+        }
+        rtcpKeyFrameTimeoutInMillis = now + rtcpKeyFrameDelayInMillis;
+      }
+    }
+
     if (udp.getSock() == -1){onFail("UDP socket closed", true);}
     return hadPack;
   }
@@ -1125,6 +1165,7 @@ namespace Mist{
   }
 
   void OutWebRTC::ackNACK(uint32_t pSSRC, uint16_t seq){
+    totalRetrans++;
     if (!outBuffers.count(pSSRC)){
       WARN_MSG("Could not answer NACK for %" PRIu32 ": we don't know this track", pSSRC);
       return;
@@ -1193,6 +1234,7 @@ namespace Mist{
         uint16_t sNum = *(rtcTrack.sorter.wantedSeqs.begin());
         if (packetLog.is_open()){packetLog << "[" << Util::bootMS() << "]" << "Sending NACK for sequence #" << sNum << std::endl;}
         stats_nacknum++;
+        totalRetrans++;
         sendRTCPFeedbackNACK(rtcTrack, sNum);
         rtcTrack.sorter.wantedSeqs.erase(sNum);
       }
@@ -1259,6 +1301,7 @@ namespace Mist{
             uint64_t ntpTime = Bit::btohll(udp.data + 8);
             uint32_t rtpTime = Bit::btohl(udp.data + 16);
             uint32_t packets = Bit::btohl(udp.data + 20);
+            totalPkts += packets;
             uint32_t bytes = Bit::btohl(udp.data + 24);
             HIGH_MSG("Received sender report for track %s (%" PRIu32 " pkts, %" PRIu32 "b) time: %" PRIu32 " RTP = %" PRIu64 " NTP", it->second.rtpToDTSC.codec.c_str(), packets, bytes, rtpTime, ntpTime);
             if (rtpTime && ntpTime){
@@ -1277,7 +1320,8 @@ namespace Mist{
         }
       }else if (pt == 73){
         //73 = receiver report
-        // \TODO Implement, maybe?
+        uint32_t packets = Bit::btoh24(udp.data + 13);
+        totalLoss = packets;
       }else{
         if (packetLog.is_open()){packetLog << "[" << Util::bootMS() << "]" << "Unknown payload type: " << pt << std::endl;}
         WARN_MSG("Unknown RTP feedback payload type: %u", pt);
@@ -1294,7 +1338,14 @@ namespace Mist{
   }
 
   void OutWebRTC::onDTSCConverterHasPacket(const DTSC::Packet &pkt){
-
+    if (!M.getBootMsOffset()){
+      meta.setBootMsOffset(Util::bootMS() - pkt.getTime());
+      packetOffset = 0;
+      setPacketOffset = true;
+    }else if (!setPacketOffset){
+      packetOffset = (Util::bootMS() - pkt.getTime()) - M.getBootMsOffset();
+      setPacketOffset = true;
+    }
 
     // extract meta data (init data, width/height, etc);
     size_t idx = M.trackIDToIndex(pkt.getTrackId(), getpid());
@@ -1311,30 +1362,16 @@ namespace Mist{
     if (codec == "VP8" && pkt.getFlag("keyframe")){extractFrameSizeFromVP8KeyFrame(pkt);}
     if (codec == "VP9" && pkt.getFlag("keyframe")){extractFrameSizeFromVP8KeyFrame(pkt);}
 
-    // create rtcp packet (set bitrate and request keyframe).
-    if (codec == "H264" || codec == "VP8" || codec == "VP9"){
-      uint64_t now = Util::bootMS();
-
-      if (now >= rtcpTimeoutInMillis){
-        WebRTCTrack &rtcTrack = webrtcTracks[idx];
-        sendRTCPFeedbackREMB(rtcTrack);
-        sendRTCPFeedbackRR(rtcTrack);
-        rtcpTimeoutInMillis = now + 1000; /* was 5000, lowered for FEC */
-      }
-
-      if (now >= rtcpKeyFrameTimeoutInMillis){
-        WebRTCTrack &rtcTrack = webrtcTracks[idx];
-        sendRTCPFeedbackPLI(rtcTrack);
-        rtcpKeyFrameTimeoutInMillis = now + rtcpKeyFrameDelayInMillis;
-      }
-    }
-
     if (!M.trackValid(idx)){
       INFO_MSG("Validated track %zu in meta", idx);
       meta.validateTrack(idx);
     }
     DONTEVEN_MSG("DTSC: %s", pkt.toSummary().c_str());
-    bufferLivePacket(pkt);
+    char *pktData;
+    size_t pktDataLen;
+    pkt.getString("data", pktData, pktDataLen);
+    bufferLivePacket(pkt.getTime() + packetOffset, pkt.getInt("offset"), idx, pktData,
+                     pktDataLen, 0, pkt.getFlag("keyframe"));
   }
 
   void OutWebRTC::onDTSCConverterHasInitData(size_t trackId, const std::string &initData){
@@ -1397,6 +1434,7 @@ namespace Mist{
     uint16_t seq = tmpPkt.getSequence();
     outBuffers[pSSRC].assign(seq, rtpOutBuffer, protectedSize);
     myConn.addUp(protectedSize);
+    totalPkts++;
 
     if (volkswagenMode){
       if (srtpWriter.protectRtp((uint8_t *)(void *)rtpOutBuffer, &protectedSize) != 0){
@@ -1721,7 +1759,7 @@ namespace Mist{
   // sequence numbers are lost it makes sense to implement this
   // too.
   void OutWebRTC::sendRTCPFeedbackNACK(const WebRTCTrack &rtcTrack, uint16_t lostSequenceNumber){
-    INFO_MSG("Requesting missing sequence number %u", lostSequenceNumber);
+    VERYHIGH_MSG("Requesting missing sequence number %u", lostSequenceNumber);
 
     std::vector<uint8_t> buffer;
     buffer.push_back(0x80 | 0x01); // V=2 (0x80) | FMT=1 (0x01)
@@ -1767,9 +1805,14 @@ namespace Mist{
   }
 
   void OutWebRTC::sendRTCPFeedbackRR(WebRTCTrack &rtcTrack){
-    stats_lossperc = (double)(rtcTrack.sorter.lostCurrent * 100.) / (double)(rtcTrack.sorter.lostCurrent + rtcTrack.sorter.packCurrent);
+    if ((rtcTrack.sorter.lostCurrent + rtcTrack.sorter.packCurrent) < 1){
+      stats_lossperc = 100.0;
+    }else{
+      stats_lossperc = (double)(rtcTrack.sorter.lostCurrent * 100.) / (double)(rtcTrack.sorter.lostCurrent + rtcTrack.sorter.packCurrent);
+    }
     stats_jitter = rtcTrack.jitter/rtcTrack.rtpToDTSC.multiplier;
     stats_lossnum = rtcTrack.sorter.lostTotal;
+    totalLoss = stats_lossnum;
 
     //Print stats at appropriate log levels
     if (stats_lossperc > 1 || stats_jitter > 20){

src/output/output_webrtc.h

@@ -143,10 +143,14 @@ namespace Mist{
     void onDTSCConverterHasInitData(const size_t trackID, const std::string &initData);
     void onRTPPacketizerHasRTPPacket(const char *data, size_t nbytes);
     void onRTPPacketizerHasRTCPPacket(const char *data, uint32_t nbytes);
+    virtual void connStats(uint64_t now, Comms::Statistics &statComm);
 
   private:
     uint64_t lastRecv;
     uint64_t lastPackMs;
+    uint64_t totalPkts;
+    uint64_t totalLoss;
+    uint64_t totalRetrans;
     std::ofstream jitterLog;
     std::ofstream packetLog;
     std::string externalAddr;
@@ -209,6 +213,7 @@ namespace Mist{
     double target_rate; ///< Target playback speed rate (1.0 = normal, 0 = auto)
 
     bool didReceiveKeyFrame; /* TODO burst delay */
+    bool setPacketOffset;
     int64_t packetOffset;    ///< For timestamp rewrite with BMO
     uint64_t lastTimeSync;
     bool firstKey;