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)
This commit is contained in:
George Kiagiadakis 2017-09-07 14:33:57 +03:00
parent 85ec6430d9
commit 286e1e62be
2 changed files with 43 additions and 41 deletions

View file

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

View file

@ -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, fmtp = GPOINTER_TO_UINT (g_hash_table_lookup (rtx->rtx_pt_map,
GUINT_TO_POINTER (gst_rtp_buffer_get_payload_type (&rtp)))); GUINT_TO_POINTER (gst_rtp_buffer_get_payload_type (&rtp))));
GST_DEBUG_OBJECT (rtx, GST_DEBUG_OBJECT (rtx, "creating rtx buffer, orig seqnum: %u, "
"retransmit seqnum: %" G_GUINT16_FORMAT ", ssrc: %" G_GUINT32_FORMAT, "rtx seqnum: %u, rtx ssrc: %X", gst_rtp_buffer_get_seq (&rtp),
seqnum, ssrc); seqnum, ssrc);
/* gst_rtp_buffer_map does not map the payload so do it now */ /* 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)) if (!gst_structure_get_uint (s, "ssrc", &ssrc))
ssrc = -1; ssrc = -1;
GST_DEBUG_OBJECT (rtx, GST_DEBUG_OBJECT (rtx, "got rtx request for seqnum: %u, ssrc: %X",
"request seqnum: %" G_GUINT32_FORMAT ", ssrc: %" G_GUINT32_FORMAT,
seqnum, ssrc); seqnum, ssrc);
GST_OBJECT_LOCK (rtx); 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); (GCompareDataFunc) buffer_queue_items_cmp, NULL);
if (iter) { if (iter) {
BufferQueueItem *item = g_sequence_get (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); 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)) if (!gst_structure_get_uint (s, "ssrc", &ssrc))
ssrc = -1; 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); 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_WARNING_OBJECT (rtx, "Payload %d not in rtx-pt-map", payload);
GST_DEBUG_OBJECT (rtx, GST_DEBUG_OBJECT (rtx,
"got caps for payload: %d->%d, ssrc: %u->%" G_GUINT32_FORMAT ": %" "got caps for payload: %d->%d, ssrc: %u->%u : %" GST_PTR_FORMAT,
GST_PTR_FORMAT, payload, GPOINTER_TO_INT (rtx_payload), ssrc, payload, GPOINTER_TO_INT (rtx_payload), ssrc, data->rtx_ssrc, caps);
data->rtx_ssrc, caps);
gst_structure_get_int (s, "clock-rate", &data->clock_rate); 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); rtptime = gst_rtp_buffer_get_timestamp (&rtp);
gst_rtp_buffer_unmap (&rtp); gst_rtp_buffer_unmap (&rtp);
GST_TRACE_OBJECT (rtx, GST_TRACE_OBJECT (rtx, "Processing buffer seqnum: %u, ssrc: %X", seqnum,
"Processing buffer seqnum: %" G_GUINT16_FORMAT ", ssrc: %" ssrc);
G_GUINT32_FORMAT, seqnum, ssrc);
/* do not store the buffer if it's payload type is unknown */ /* 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))) { if (g_hash_table_contains (rtx->rtx_pt_map, GUINT_TO_POINTER (payload_type))) {