Cast: Wire up sending status log messages from sender to receiver.

Includes both handling of the received message in the receiver and
sending the message in the sender. The acctual packeiztion and parser
has been landed in prior CLs.

Review URL: https://codereview.chromium.org/105883010

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@240122 0039d316-1c4b-4281-b951-d872f2087c98

7 files changed, 143 insertions, 41 deletions

diff --git a/media/cast/audio_sender/audio_sender.cc b/media/cast/audio_sender/audio_sender.cc
index 00f4313..ba7dc7e 100644
--- a/media/cast/audio_sender/audio_sender.cc
+++ b/media/cast/audio_sender/audio_sender.cc
@@ -200,7 +200,9 @@ void AudioSender::ScheduleNextRtcpReport() {
 
 void AudioSender::SendRtcpReport() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
-  rtcp_.SendRtcpFromRtpSender(NULL);  // TODO(pwestin): add logging.
+  // We don't send audio logging messages since all captured audio frames will
+  // be sent.
+  rtcp_.SendRtcpFromRtpSender(NULL);
   ScheduleNextRtcpReport();
 }
 
diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc
index 16117b0..ea96b94 100644
--- a/media/cast/logging/logging_impl.cc
+++ b/media/cast/logging/logging_impl.cc
@@ -54,7 +54,6 @@ void LoggingImpl::InsertFrameEventWithSize(CastLoggingEvent event,
         TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "frame_size",
         frame_size);
   }
-
 }
 
 void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event,
@@ -69,11 +68,11 @@ void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event,
   if (config_.enable_uma_stats) {
     UMA_HISTOGRAM_TIMES(CastLoggingToString(event), delay);
   }
-   if (config_.enable_tracing) {
-      std::string event_string = CastLoggingToString(event);
-      TRACE_EVENT_INSTANT2(event_string.c_str(), "FED",
-          TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "delay",
-          delay.InMilliseconds());
+  if (config_.enable_tracing) {
+    std::string event_string = CastLoggingToString(event);
+    TRACE_EVENT_INSTANT2(event_string.c_str(), "FED",
+        TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "delay",
+        delay.InMilliseconds());
   }
 }
 
@@ -95,7 +94,6 @@ void LoggingImpl::InsertPacketListEvent(CastLoggingEvent event,
     InsertPacketEvent(event, rtp_timestamp, kFrameIdUnknown, packet_id,
                       max_packet_id, packet.size());
   }
-
 }
 
 void LoggingImpl::InsertPacketEvent(CastLoggingEvent event,
@@ -111,12 +109,12 @@ void LoggingImpl::InsertPacketEvent(CastLoggingEvent event,
     stats_.InsertPacketEvent(event, rtp_timestamp, frame_id, packet_id,
                              max_packet_id, size);
   }
-    if (config_.enable_tracing) {
-      std::string event_string = CastLoggingToString(event);
-      TRACE_EVENT_INSTANT2(event_string.c_str(), "PE",
-          TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp,
-          "packet_id", packet_id);
-    }
+  if (config_.enable_tracing) {
+    std::string event_string = CastLoggingToString(event);
+    TRACE_EVENT_INSTANT2(event_string.c_str(), "PE",
+        TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp,
+        "packet_id", packet_id);
+  }
 }
 
 void LoggingImpl::InsertGenericEvent(CastLoggingEvent event, int value) {
@@ -135,7 +133,6 @@ void LoggingImpl::InsertGenericEvent(CastLoggingEvent event, int value) {
   }
 }
 
-
 // should just get the entire class, would be much easier.
 FrameRawMap LoggingImpl::GetFrameRawData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
@@ -207,7 +204,7 @@ const GenericStatsMap* LoggingImpl::GetGenericStatsData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   // Get stats data.
   const GenericStatsMap* stats = stats_.GetGenericStatsData();
-   if (config_.enable_uma_stats) {
+  if (config_.enable_uma_stats) {
     GenericStatsMap::const_iterator it;
     for (it = stats->begin(); it != stats->end(); ++it) {
       if (it->second > 0) {
diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h
index 6c2d863..34021b7 100644
--- a/media/cast/logging/logging_impl.h
+++ b/media/cast/logging/logging_impl.h
@@ -29,6 +29,8 @@ class LoggingImpl : public base::NonThreadSafe {
 
   ~LoggingImpl();
 
+  // TODO(pwestin): Add argument to API to send in time of event instead of
+  // grabbing now.
   void InsertFrameEvent(CastLoggingEvent event,
                         uint32 rtp_timestamp,
                         uint32 frame_id);
diff --git a/media/cast/logging/logging_raw.cc b/media/cast/logging/logging_raw.cc
index 93a65f0..6a38961 100644
--- a/media/cast/logging/logging_raw.cc
+++ b/media/cast/logging/logging_raw.cc
@@ -47,6 +47,7 @@ void LoggingRaw::InsertFrameEventWithDelay(CastLoggingEvent event,
   DCHECK(it != frame_map_.end());
   it->second.delay_delta = delay;
 }
+
 void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event,
                                       uint32 frame_id,
                                       uint32 rtp_timestamp) {
diff --git a/media/cast/rtcp/rtcp.cc b/media/cast/rtcp/rtcp.cc
index 7a1f04a..4ea4bc9 100644
--- a/media/cast/rtcp/rtcp.cc
+++ b/media/cast/rtcp/rtcp.cc
@@ -59,8 +59,9 @@ RtcpReceiverFrameLogMessage::~RtcpReceiverFrameLogMessage() {}
 
 class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback {
  public:
-  explicit LocalRtcpReceiverFeedback(Rtcp* rtcp)
-      : rtcp_(rtcp) {
+  LocalRtcpReceiverFeedback(Rtcp* rtcp,
+                           scoped_refptr<CastEnvironment> cast_environment)
+      : rtcp_(rtcp), cast_environment_(cast_environment) {
   }
 
   virtual void OnReceivedSenderReport(
@@ -86,20 +87,83 @@ class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback {
 
   virtual void OnReceivedReceiverLog(
       const RtcpReceiverLogMessage& receiver_log) OVERRIDE {
-    // TODO(pwestin): Implement.
     // Add received log messages into our log system.
-    NOTIMPLEMENTED();
+    RtcpReceiverLogMessage::const_iterator it = receiver_log.begin();
+
+    for (; it != receiver_log.end(); ++it) {
+      uint32 rtp_timestamp = it->rtp_timestamp_;
+
+      RtcpReceiverEventLogMessages::const_iterator event_it =
+          it->event_log_messages_.begin();
+      for (; event_it != it->event_log_messages_.end(); ++event_it) {
+        // TODO(pwestin): we need to send in the event_it->event_timestamp to
+        // the log system too.
+        switch (event_it->type) {
+          case kPacketReceived:
+            cast_environment_->Logging()->InsertPacketEvent(kPacketReceived,
+                rtp_timestamp, kFrameIdUnknown, event_it->packet_id, 0, 0);
+            break;
+          case kAckSent:
+          case kAudioFrameDecoded:
+          case kVideoFrameDecoded:
+            cast_environment_->Logging()->InsertFrameEvent(event_it->type,
+                rtp_timestamp, kFrameIdUnknown);
+            break;
+          case kAudioPlayoutDelay:
+          case kVideoRenderDelay:
+            cast_environment_->Logging()->InsertFrameEventWithDelay(
+                event_it->type, rtp_timestamp, kFrameIdUnknown,
+                event_it->delay_delta);
+            break;
+          default:
+            VLOG(2) << "Received log message via RTCP that we did not expect: "
+                    << static_cast<int>(event_it->type);
+            break;
+        }
+      }
+    }
   }
 
   virtual void OnReceivedSenderLog(
-    const RtcpSenderLogMessage& sender_log)  OVERRIDE {
-    // TODO(pwestin): Implement.
-    // Add received log messages into our log system.
-    NOTIMPLEMENTED();
+      const RtcpSenderLogMessage& sender_log)  OVERRIDE {
+    RtcpSenderLogMessage::const_iterator it = sender_log.begin();
+
+    for (; it != sender_log.end(); ++it) {
+      uint32 rtp_timestamp = it->rtp_timestamp;
+      CastLoggingEvent log_event = kUnknown;
+
+      // These events are provided to know the status of frames that never
+      // reached the receiver. The timing information for these events are not
+      // relevant and is not sent over the wire.
+      switch (it->frame_status) {
+        case kRtcpSenderFrameStatusDroppedByFlowControl:
+          // A frame that have been dropped by the flow control would have
+          // kVideoFrameCaptured as its last event in the log.
+          log_event = kVideoFrameCaptured;
+          break;
+        case kRtcpSenderFrameStatusDroppedByEncoder:
+          // A frame that have been dropped by the encoder would have
+          // kVideoFrameSentToEncoder as its last event in the log.
+          log_event = kVideoFrameSentToEncoder;
+          break;
+        case kRtcpSenderFrameStatusSentToNetwork:
+          // A frame that have be encoded is always sent to the network. We
+          // do not add a new log entry for this.
+          log_event = kVideoFrameEncoded;
+          break;
+        default:
+          continue;
+      }
+      // TODO(pwestin): how do we handle the truncated rtp_timestamp?
+      // Add received log messages into our log system.
+      cast_environment_->Logging()->InsertFrameEvent(log_event, rtp_timestamp,
+          kFrameIdUnknown);
+    }
   }
 
  private:
   Rtcp* rtcp_;
+  scoped_refptr<CastEnvironment> cast_environment_;
 };
 
 Rtcp::Rtcp(scoped_refptr<CastEnvironment> cast_environment,
@@ -118,7 +182,7 @@ Rtcp::Rtcp(scoped_refptr<CastEnvironment> cast_environment,
       remote_ssrc_(remote_ssrc),
       rtp_sender_statistics_(rtp_sender_statistics),
       rtp_receiver_statistics_(rtp_receiver_statistics),
-      receiver_feedback_(new LocalRtcpReceiverFeedback(this)),
+      receiver_feedback_(new LocalRtcpReceiverFeedback(this, cast_environment)),
       rtt_feedback_(new LocalRtcpRttFeedback(this)),
       rtcp_sender_(new RtcpSender(cast_environment, paced_packet_sender,
                                   local_ssrc, c_name)),
diff --git a/media/cast/rtcp/rtcp.h b/media/cast/rtcp/rtcp.h
index f89600c..aa083a5 100644
--- a/media/cast/rtcp/rtcp.h
+++ b/media/cast/rtcp/rtcp.h
@@ -40,17 +40,6 @@ class RtcpSenderFeedback {
   virtual ~RtcpSenderFeedback() {}
 };
 
-class RtcpReceivedLog {
- public:
-  virtual void OnReceivedReceiverLog(
-      const RtcpReceiverLogMessage& receiver_log) = 0;
-
-  virtual void OnReceivedSenderLog(
-      const RtcpSenderLogMessage& sender_log) = 0;
-
-  virtual ~RtcpReceivedLog() {}
-};
-
 class RtpSenderStatistics {
  public:
   virtual void GetStatistics(const base::TimeTicks& now,
diff --git a/media/cast/video_sender/video_sender.cc b/media/cast/video_sender/video_sender.cc
index aa0e162..91679d9 100644
--- a/media/cast/video_sender/video_sender.cc
+++ b/media/cast/video_sender/video_sender.cc
@@ -215,7 +215,7 @@ void VideoSender::IncomingRtcpPacket(const uint8* packet, size_t length,
 void VideoSender::ScheduleNextRtcpReport() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   base::TimeDelta time_to_next = rtcp_->TimeToSendNextRtcpReport() -
-     cast_environment_->Clock()->NowTicks();
+      cast_environment_->Clock()->NowTicks();
 
   time_to_next = std::max(time_to_next,
       base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs));
@@ -227,7 +227,54 @@ void VideoSender::ScheduleNextRtcpReport() {
 
 void VideoSender::SendRtcpReport() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
-  rtcp_->SendRtcpFromRtpSender(NULL);  // TODO(pwestin): add logging.
+
+  RtcpSenderLogMessage sender_log_message;
+  const FrameRawMap& frame_raw_map =
+      cast_environment_->Logging()->GetFrameRawData();
+
+  FrameRawMap::const_iterator it = frame_raw_map.begin();
+  while (it != frame_raw_map.end()) {
+    RtcpSenderFrameLogMessage frame_message;
+    frame_message.rtp_timestamp = it->first;
+    frame_message.frame_status = kRtcpSenderFrameStatusUnknown;
+    if (it->second.type.empty()) {
+      ++it;
+      continue;
+    }
+    CastLoggingEvent last_event = it->second.type.back();
+    switch (last_event) {
+      case kVideoFrameCaptured:
+        frame_message.frame_status = kRtcpSenderFrameStatusDroppedByFlowControl;
+        break;
+      case kVideoFrameSentToEncoder:
+        frame_message.frame_status = kRtcpSenderFrameStatusDroppedByEncoder;
+        break;
+      case kVideoFrameEncoded:
+        frame_message.frame_status = kRtcpSenderFrameStatusSentToNetwork;
+        break;
+      default:
+        ++it;
+        continue;
+    }
+    ++it;
+    if (it == frame_raw_map.end()) {
+      // Last message on our map; only send if it is kVideoFrameEncoded.
+      if (last_event != kVideoFrameEncoded) {
+        // For other events we will wait for it to finish and report the result
+        // in the next report.
+        break;
+      }
+    }
+    sender_log_message.push_back(frame_message);
+  }
+  rtcp_->SendRtcpFromRtpSender(&sender_log_message);
+  if (!sender_log_message.empty()) {
+    VLOG(1) << "Failed to send all log messages";
+  }
+
+  // TODO(pwestin): When we start pulling out the logging by other means we need
+  // to synchronize this.
+  cast_environment_->Logging()->Reset();
   ScheduleNextRtcpReport();
 }
 
@@ -256,7 +303,7 @@ void VideoSender::ResendCheck() {
     if (time_since_last_send > rtp_max_delay_) {
       if (last_acked_frame_id_ == -1) {
         // We have not received any ack, send a key frame.
-         video_encoder_controller_->GenerateKeyFrame();
+        video_encoder_controller_->GenerateKeyFrame();
         last_acked_frame_id_ = -1;
         last_sent_frame_id_ = -1;
         UpdateFramesInFlight();
@@ -280,8 +327,8 @@ void VideoSender::ScheduleNextSkippedFramesCheck() {
         base::TimeDelta::FromMilliseconds(kSkippedFramesCheckPeriodkMs);
   } else {
     time_to_next = last_checked_skip_count_time_ -
-         cast_environment_->Clock()->NowTicks() +
-         base::TimeDelta::FromMilliseconds(kSkippedFramesCheckPeriodkMs);
+        cast_environment_->Clock()->NowTicks() +
+        base::TimeDelta::FromMilliseconds(kSkippedFramesCheckPeriodkMs);
   }
   time_to_next = std::max(time_to_next,
       base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs));