Added log messages for important call setup events: first packet sent/received

webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc

Index: webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
index 2aa4961cdc77d98490c607ed23945617228bf760..27ad420c8a549dfdc3c8f6bcd139bf6f47d90f07 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
+++ b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
@@ -12,6 +12,7 @@
 
 #include <string.h>
 
+#include "webrtc/base/logging.h"
 #include "webrtc/base/trace_event.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
 #include "webrtc/modules/rtp_rtcp/source/byte_io.h"
@@ -45,7 +46,8 @@ RTPSenderAudio::RTPSenderAudio(Clock* clock,
       _cngSWBPayloadType(-1),
       _cngFBPayloadType(-1),
       _lastPayloadType(-1),
-      _audioLevel_dBov(0) {}
+      _audioLevel_dBov(0),
+      _firstPacketSent(false) {}
 
 RTPSenderAudio::~RTPSenderAudio() {}
 
@@ -342,9 +344,15 @@ int32_t RTPSenderAudio::SendAudio(FrameType frameType,
       memcpy(dataBuffer + rtpHeaderLength, payloadData, payloadSize);
     }
   }
+
+  bool firstPacket;
   {
     CriticalSectionScoped cs(_sendAudioCritsect.get());
     _lastPayloadType = payloadType;
+    firstPacket = !_firstPacketSent;
+    if (firstPacket) {
+      _firstPacketSent = true;
+    }

[pthatcher1, 2016/03/05 01:17:05]

Nit: This might be more clear as:

bool firstPacket = false;
...

if (!_firstPacketSent) {
  firstPacket = true;
  _firstPacketSent = true;
}

[skvlad, 2016/03/07 19:36:53]

Done.

   }
   // Update audio level extension, if included.
   size_t packetSize = payloadSize + rtpHeaderLength;
@@ -357,10 +365,15 @@ int32_t RTPSenderAudio::SendAudio(FrameType frameType,
   TRACE_EVENT_ASYNC_END2("webrtc", "Audio", captureTimeStamp, "timestamp",
                          _rtpSender->Timestamp(), "seqnum",
                          _rtpSender->SequenceNumber());
-  return _rtpSender->SendToNetwork(dataBuffer, payloadSize, rtpHeaderLength,
+  int32_t sendResult = _rtpSender->SendToNetwork(dataBuffer, payloadSize,

[danilchap, 2016/03/07 09:29:11]

SendToNetwork doesn't send packet immediately. It post packet to pacer that send
it in a different thread.
You may want to check RtpSender::SendPacketToNework instead.
Also, RtpSender already has a flag media_has_been_sent_ that is set to true
after first sent packet.

[pthatcher1, 2016/03/07 17:28:33]

That's a good point.  

Actually, we might want to record *both* timestamps, before and after the pacer,
so we know the impact of the pacer on the latency of the first frame.  

So, perhaps just note in these logs statements that it's pre-pacer.  

As for when we really send something on the network, we'd actually want push
that further than the RtpSender, but all the way out to perhaps MediaChannel or
maybe even P2pTransportChannel.  To do so, we'd need that layer to know it's a
special packet.  Luckily, we already have a mechanism in which the
P2pTransportChannel reports back when a specific packet has been sent.  Perhaps
we could use that to know when a packet really hits the network.

All that said, I think we could do so in a secondary CL.  For our purposes right
now, knowing the pre-pacer time is probably enough, as long as we log that it's
pre-pacer.

[skvlad, 2016/03/07 19:36:53]

Changed the log line to say the packet hasn't gone through the pacer yet.

+                                   rtpHeaderLength,
                                    TickTime::MillisecondTimestamp(),
                                    kAllowRetransmission,
                                    RtpPacketSender::kHighPriority);
+  if (firstPacket) {
+    LOG(LS_INFO) << "First audio RTP packet sent";
+  }
+  return sendResult;
 }
 
 // Audio level magnitude and voice activity flag are set for each RTP packet