rtprtx{send,receive}: improve the debug messages

* use INFO/DEBUG/LOG/TRACE equaly and meaningfully;
  previously rtprtxsend:LOG and rtprtxreceive:LOG would generate
  a totally different amount of log traffic and sometimes it was
  impossible to see the information you wanted without useless
  spam being printed around
* improve the wording, give a reasonable and self-explanatory
  amount of information
* print SSRCs in hex
* avoid G_FOO_FORMAT for readability (we are just printing integers)

diff --git a/gst/rtpmanager/gstrtprtxreceive.c b/gst/rtpmanager/gstrtprtxreceive.c
index ce3466e..9a8a666 100644 (file)
--- a/gst/rtpmanager/gstrtprtxreceive.c
+++ b/gst/rtpmanager/gstrtprtxreceive.c
@@ -339,8 +339,7 @@ gst_rtp_rtx_receive_src_event (GstPad * pad, GstObject * parent,
         if (!gst_structure_get_uint (s, "ssrc", &ssrc))
           ssrc = -1;
 
-        GST_DEBUG_OBJECT (rtx,
-            "request seqnum: %" G_GUINT32_FORMAT ", ssrc: %" G_GUINT32_FORMAT,
+        GST_DEBUG_OBJECT (rtx, "got rtx request for seqnum: %u, ssrc: %X",
             seqnum, ssrc);
 
         GST_OBJECT_LOCK (rtx);
@@ -356,8 +355,8 @@ gst_rtp_rtx_receive_src_event (GstPad * pad, GstObject * parent,
         if (g_hash_table_lookup_extended (rtx->ssrc2_ssrc1_map,
                 GUINT_TO_POINTER (ssrc), NULL, &ssrc2)
             && GPOINTER_TO_UINT (ssrc2) != GPOINTER_TO_UINT (ssrc)) {
-          GST_DEBUG_OBJECT (rtx, "Retransmited stream %" G_GUINT32_FORMAT
-              " already associated to its master", GPOINTER_TO_UINT (ssrc2));
+          GST_TRACE_OBJECT (rtx, "Retransmited stream %X already associated "
+              "to its master, %X", GPOINTER_TO_UINT (ssrc2), ssrc);
         } else {
           SsrcAssoc *assoc;
 
@@ -367,15 +366,18 @@ gst_rtp_rtx_receive_src_event (GstPad * pad, GstObject * parent,
           if (g_hash_table_lookup_extended (rtx->seqnum_ssrc1_map,
                   GUINT_TO_POINTER (seqnum), NULL, (gpointer *) & assoc)) {
             if (assoc->ssrc == ssrc) {
+              /* same seqnum, same ssrc */
+
               /* do nothing because we have already considered this request
                * The jitter may be too impatient of the rtx packet has been
                * lost too.
                * It does not mean we reject the event, we still want to forward
                * the request to the gstrtpsession to be translater into a FB NACK
                */
-              GST_DEBUG_OBJECT (rtx, "Duplicated request seqnum: %"
-                  G_GUINT32_FORMAT ", ssrc1: %" G_GUINT32_FORMAT, seqnum, ssrc);
+              GST_LOG_OBJECT (rtx, "Duplicate request: seqnum: %u, ssrc: %X",
+                  seqnum, ssrc);
             } else {
+              /* same seqnum, different ssrc */
 
               /* If the association attempt is larger than ASSOC_TIMEOUT,
                * then we give up on it, and try this one.
@@ -395,9 +397,10 @@ gst_rtp_rtx_receive_src_event (GstPad * pad, GstObject * parent,
                     GUINT_TO_POINTER (seqnum));
                 goto retransmit;
               } else {
-                GST_DEBUG_OBJECT (rtx,
-                    "reject request for seqnum %" G_GUINT32_FORMAT
-                    " of master stream %" G_GUINT32_FORMAT, seqnum, ssrc);
+                GST_INFO_OBJECT (rtx, "rejecting request for seqnum %u"
+                    " of master stream %X; there is already a pending request "
+                    "for the same seqnum on ssrc %X that has not expired",
+                    seqnum, ssrc, assoc->ssrc);
 
                 /* do not forward the event as we are rejecting this request */
                 GST_OBJECT_UNLOCK (rtx);
@@ -415,9 +418,8 @@ gst_rtp_rtx_receive_src_event (GstPad * pad, GstObject * parent,
           }
         }
 
-        GST_DEBUG_OBJECT (rtx,
-            "packet number %" G_GUINT32_FORMAT " of master stream %"
-            G_GUINT32_FORMAT " needs to be retransmitted", seqnum, ssrc);
+        GST_DEBUG_OBJECT (rtx, "packet number %u of master stream %X"
+            " needs to be retransmitted", seqnum, ssrc);
 
         GST_OBJECT_UNLOCK (rtx);
       }
@@ -573,14 +575,17 @@ gst_rtp_rtx_receive_chain (GstPad * pad, GstObject * parent, GstBuffer * buffer)
         GPOINTER_TO_UINT (g_hash_table_lookup (rtx->rtx_pt_map,
             GUINT_TO_POINTER (payload_type)));
 
+    GST_DEBUG_OBJECT (rtx, "Got rtx packet: rtx seqnum %u, rtx ssrc %X, "
+        "rtx pt %u, orig seqnum %u, orig pt %u", seqnum, ssrc, payload_type,
+        orign_seqnum, origin_payload_type);
+
     /* first we check if we already have associated this retransmission stream
      * to a master stream */
     if (g_hash_table_lookup_extended (rtx->ssrc2_ssrc1_map,
             GUINT_TO_POINTER (ssrc), NULL, &ssrc1)) {
-      GST_DEBUG_OBJECT (rtx,
-          "packet is from retransmission stream %" G_GUINT32_FORMAT
-          " already associated to master stream %" G_GUINT32_FORMAT, ssrc,
-          GPOINTER_TO_UINT (ssrc1));
+      GST_TRACE_OBJECT (rtx,
+          "packet is from retransmission stream %X already associated to "
+          "master stream %X", ssrc, GPOINTER_TO_UINT (ssrc1));
       ssrc2 = ssrc;
     } else {
       SsrcAssoc *assoc;
@@ -590,17 +595,17 @@ gst_rtp_rtx_receive_chain (GstPad * pad, GstObject * parent, GstBuffer * buffer)
        * history */
       if (g_hash_table_lookup_extended (rtx->seqnum_ssrc1_map,
               GUINT_TO_POINTER (orign_seqnum), NULL, (gpointer *) & assoc)) {
-        GST_DEBUG_OBJECT (rtx,
-            "associate retransmitted stream %" G_GUINT32_FORMAT
-            " to master stream %" G_GUINT32_FORMAT " thanks to packet %"
-            G_GUINT16_FORMAT "", ssrc, assoc->ssrc, orign_seqnum);
+        GST_LOG_OBJECT (rtx,
+            "associating retransmitted stream %X to master stream %X thanks "
+            "to rtx packet %u (orig seqnum %u)", ssrc, assoc->ssrc, seqnum,
+            orign_seqnum);
         ssrc1 = GUINT_TO_POINTER (assoc->ssrc);
         ssrc2 = ssrc;
 
         /* just put a guard */
         if (GPOINTER_TO_UINT (ssrc1) == ssrc2)
           GST_WARNING_OBJECT (rtx, "RTX receiver ssrc2_ssrc1_map bad state, "
-              "ssrc %" G_GUINT32_FORMAT " are the same\n", ssrc);
+              "master and rtx SSRCs are the same (%X)\n", ssrc);
 
         /* free the spot so that this seqnum can be used to do another
          * association */
@@ -620,9 +625,9 @@ gst_rtp_rtx_receive_chain (GstPad * pad, GstObject * parent, GstBuffer * buffer)
 
       } else {
         /* we are not able to associate this rtx packet with a master stream */
-        GST_DEBUG_OBJECT (rtx,
-            "drop rtx packet because its orign_seqnum %" G_GUINT16_FORMAT
-            " is not in pending retransmission requests", orign_seqnum);
+        GST_INFO_OBJECT (rtx,
+            "dropping rtx packet %u because its orig seqnum (%u) is not in our"
+            " pending retransmission requests", seqnum, orign_seqnum);
         drop = TRUE;
       }
     }
@@ -652,13 +657,13 @@ gst_rtp_rtx_receive_chain (GstPad * pad, GstObject * parent, GstBuffer * buffer)
   /* push the packet */
   if (is_rtx) {
     gst_buffer_unref (buffer);
-    GST_LOG_OBJECT (rtx, "push packet seqnum:%" G_GUINT16_FORMAT
-        " from a restransmission stream ssrc2:%" G_GUINT32_FORMAT " (src %"
-        G_GUINT32_FORMAT ")", orign_seqnum, ssrc2, GPOINTER_TO_UINT (ssrc1));
+    GST_LOG_OBJECT (rtx, "pushing packet seqnum:%u from restransmission "
+        "stream ssrc: %X (master ssrc %X)", orign_seqnum, ssrc2,
+        GPOINTER_TO_UINT (ssrc1));
     ret = gst_pad_push (rtx->srcpad, new_buffer);
   } else {
-    GST_LOG_OBJECT (rtx, "push packet seqnum:%" G_GUINT16_FORMAT
-        " from a master stream ssrc: %" G_GUINT32_FORMAT, seqnum, ssrc);
+    GST_TRACE_OBJECT (rtx, "pushing packet seqnum:%u from master stream "
+        "ssrc: %X", seqnum, ssrc);
     ret = gst_pad_push (rtx->srcpad, buffer);
   }
 

diff --git a/gst/rtpmanager/gstrtprtxsend.c b/gst/rtpmanager/gstrtprtxsend.c
index dda58c8..4329d84 100644 (file)
--- a/gst/rtpmanager/gstrtprtxsend.c
+++ b/gst/rtpmanager/gstrtprtxsend.c
@@ -387,8 +387,8 @@ gst_rtp_rtx_buffer_new (GstRtpRtxSend * rtx, GstBuffer * buffer)
   fmtp = GPOINTER_TO_UINT (g_hash_table_lookup (rtx->rtx_pt_map,
           GUINT_TO_POINTER (gst_rtp_buffer_get_payload_type (&rtp))));
 
-  GST_DEBUG_OBJECT (rtx,
-      "retransmit seqnum: %" G_GUINT16_FORMAT ", ssrc: %" G_GUINT32_FORMAT,
+  GST_DEBUG_OBJECT (rtx, "creating rtx buffer, orig seqnum: %u, "
+      "rtx seqnum: %u, rtx ssrc: %X", gst_rtp_buffer_get_seq (&rtp),
       seqnum, ssrc);
 
   /* gst_rtp_buffer_map does not map the payload so do it now */
@@ -468,8 +468,7 @@ gst_rtp_rtx_send_src_event (GstPad * pad, GstObject * parent, GstEvent * event)
         if (!gst_structure_get_uint (s, "ssrc", &ssrc))
           ssrc = -1;
 
-        GST_DEBUG_OBJECT (rtx,
-            "request seqnum: %" G_GUINT32_FORMAT ", ssrc: %" G_GUINT32_FORMAT,
+        GST_DEBUG_OBJECT (rtx, "got rtx request for seqnum: %u, ssrc: %X",
             seqnum, ssrc);
 
         GST_OBJECT_LOCK (rtx);
@@ -489,7 +488,7 @@ gst_rtp_rtx_send_src_event (GstPad * pad, GstObject * parent, GstEvent * event)
               (GCompareDataFunc) buffer_queue_items_cmp, NULL);
           if (iter) {
             BufferQueueItem *item = g_sequence_get (iter);
-            GST_DEBUG_OBJECT (rtx, "found %" G_GUINT16_FORMAT, item->seqnum);
+            GST_LOG_OBJECT (rtx, "found %u", item->seqnum);
             rtx_buf = gst_rtp_rtx_buffer_new (rtx, item->buffer);
           }
         }
@@ -508,7 +507,7 @@ gst_rtp_rtx_send_src_event (GstPad * pad, GstObject * parent, GstEvent * event)
         if (!gst_structure_get_uint (s, "ssrc", &ssrc))
           ssrc = -1;
 
-        GST_DEBUG_OBJECT (rtx, "collision ssrc: %" G_GUINT32_FORMAT, ssrc);
+        GST_DEBUG_OBJECT (rtx, "got ssrc collision, ssrc: %X", ssrc);
 
         GST_OBJECT_LOCK (rtx);
 
@@ -615,9 +614,8 @@ gst_rtp_rtx_send_sink_event (GstPad * pad, GstObject * parent, GstEvent * event)
         GST_WARNING_OBJECT (rtx, "Payload %d not in rtx-pt-map", payload);
 
       GST_DEBUG_OBJECT (rtx,
-          "got caps for payload: %d->%d, ssrc: %u->%" G_GUINT32_FORMAT ": %"
-          GST_PTR_FORMAT, payload, GPOINTER_TO_INT (rtx_payload), ssrc,
-          data->rtx_ssrc, caps);
+          "got caps for payload: %d->%d, ssrc: %u->%u : %" GST_PTR_FORMAT,
+          payload, GPOINTER_TO_INT (rtx_payload), ssrc, data->rtx_ssrc, caps);
 
       gst_structure_get_int (s, "clock-rate", &data->clock_rate);
 
@@ -694,9 +692,8 @@ process_buffer (GstRtpRtxSend * rtx, GstBuffer * buffer)
   rtptime = gst_rtp_buffer_get_timestamp (&rtp);
   gst_rtp_buffer_unmap (&rtp);
 
-  GST_TRACE_OBJECT (rtx,
-      "Processing buffer seqnum: %" G_GUINT16_FORMAT ", ssrc: %"
-      G_GUINT32_FORMAT, seqnum, ssrc);
+  GST_TRACE_OBJECT (rtx, "Processing buffer seqnum: %u, ssrc: %X", seqnum,
+      ssrc);
 
   /* do not store the buffer if it's payload type is unknown */
   if (g_hash_table_contains (rtx->rtx_pt_map, GUINT_TO_POINTER (payload_type))) {