Cast: Updating logging and tests

1. Calling logging when applicable. 
2. Added an end2end test to for logging. 
3. Removing old files (where already removed, and then somehow added back). 

Open issues: Calculation of (access to) rtp_timestamp for audio and for the vp8_decoder. TODO's were added.

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

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

17 files changed, 239 insertions, 239 deletions

diff --git a/media/cast/audio_receiver/audio_receiver.cc b/media/cast/audio_receiver/audio_receiver.cc
index ff9774c..01e0026 100644
--- a/media/cast/audio_receiver/audio_receiver.cc
+++ b/media/cast/audio_receiver/audio_receiver.cc
@@ -224,10 +224,9 @@ void AudioReceiver::DecodeAudioFrameThread(
   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   base::TimeTicks playout_time;
   playout_time = GetPlayoutTime(now, rtp_timestamp);
-  base::TimeDelta diff = playout_time - now;
 
-  cast_environment_->Logging()->InsertFrameEvent(kAudioPlayoutDelay,
-      rtp_timestamp, diff.InMilliseconds());
+  cast_environment_->Logging()->InsertFrameEventWithDelay(kAudioPlayoutDelay,
+      rtp_timestamp, kFrameIdUnknown, playout_time - now);
 
   // Frame is ready - Send back to the main thread.
   cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
diff --git a/media/cast/audio_sender/audio_encoder.cc b/media/cast/audio_sender/audio_encoder.cc
index bac2bc2..a82d1de 100644
--- a/media/cast/audio_sender/audio_encoder.cc
+++ b/media/cast/audio_sender/audio_encoder.cc
@@ -20,6 +20,13 @@
 namespace media {
 namespace cast {
 
+void LogAudioEncodedEvent(CastEnvironment* const cast_environment,
+                          const base::TimeTicks& recorded_time) {
+  // TODO(mikhal): Resolve timestamp calculation for audio.
+  cast_environment->Logging()->InsertFrameEvent(kAudioFrameEncoded,
+      GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown);
+}
+
 // Base class that handles the common problem of feeding one or more AudioBus'
 // data into a 10 ms buffer and then, once the buffer is full, encoding the
 // signal and emitting an EncodedAudioFrame via the FrameEncodedCallback.
@@ -277,6 +284,8 @@ void AudioEncoder::EncodeAudio(
     const base::Closure& done_callback) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::AUDIO_ENCODER));
   impl_->EncodeAudio(audio_bus, recorded_time, done_callback);
+  cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
+      base::Bind(LogAudioEncodedEvent, cast_environment_, recorded_time));
 }
 
 }  // namespace cast
diff --git a/media/cast/audio_sender/audio_sender.cc b/media/cast/audio_sender/audio_sender.cc
index 875b683..00f4313 100644
--- a/media/cast/audio_sender/audio_sender.cc
+++ b/media/cast/audio_sender/audio_sender.cc
@@ -108,6 +108,10 @@ void AudioSender::InsertAudio(const AudioBus* audio_bus,
                               const base::Closure& done_callback) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   DCHECK(audio_encoder_.get()) << "Invalid internal state";
+  // TODO(mikhal): Resolve calculation of the audio rtp_timestamp for logging.
+  // This is a tmp solution to allow the code to build.
+  cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived,
+        GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown);
   audio_encoder_->InsertAudio(audio_bus, recorded_time, done_callback);
 }
 
diff --git a/media/cast/cast_sender_impl.cc b/media/cast/cast_sender_impl.cc
index db24b5d..b6e5eb6 100644
--- a/media/cast/cast_sender_impl.cc
+++ b/media/cast/cast_sender_impl.cc
@@ -28,9 +28,6 @@ class LocalFrameInput : public FrameInput {
       const scoped_refptr<media::VideoFrame>& video_frame,
       const base::TimeTicks& capture_time,
       const base::Closure& callback) OVERRIDE {
-  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameReceived,
-      GetVideoRtpTimestamp(capture_time), kFrameIdUnknown);
-
     cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
         base::Bind(&VideoSender::InsertRawVideoFrame, video_sender_,
             video_frame, capture_time, callback));
@@ -47,8 +44,6 @@ class LocalFrameInput : public FrameInput {
   virtual void InsertAudio(const AudioBus* audio_bus,
                            const base::TimeTicks& recorded_time,
                            const base::Closure& done_callback) OVERRIDE {
-    cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived,
-        GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown);
     cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
         base::Bind(&AudioSender::InsertAudio, audio_sender_,
             audio_bus, recorded_time, done_callback));
diff --git a/media/cast/logging/logging.cc b/media/cast/logging/logging.cc
deleted file mode 100644
index 7f2658c..0000000
--- a/media/cast/logging/logging.cc
+++ /dev/null
@@ -1,113 +0,0 @@
-// Copyright 2013 The Chromium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style license that can be
-// found in the LICENSE file.
-
-#include "media/cast/logging/logging.h"
-
-#include "base/debug/trace_event.h"
-#include "base/logging.h"
-#include "base/metrics/histogram.h"
-
-namespace media {
-namespace cast {
-
-Logging::Logging(base::TickClock* clock)
-    : clock_(clock),
-      frame_map_(),
-      packet_map_(),
-      generic_map_(),
-      weak_factory_(this) {}
-
-Logging::~Logging() {}
-
-void Logging::InsertFrameEvent(CastLoggingEvent event,
-                               uint32 rtp_timestamp,
-                               uint32 frame_id) {
-  // Is this a new event?
-  FrameLogMap::iterator it = frame_map_.find(event);
-  if (it == frame_map_.end()) {
-    // Create new entry.
-    FrameLogData data(clock_);
-    data.Insert(rtp_timestamp, frame_id);
-    frame_map_.insert(std::make_pair(event, &data));
-  } else {
-    // Insert to existing entry.
-    it->second->Insert(rtp_timestamp, frame_id);
-  }
-}
-
-void Logging::InsertFrameEventWithSize(CastLoggingEvent event,
-                                       uint32 rtp_timestamp,
-                                       uint32 frame_id,
-                                       int size) {
-  // Is this a new event?
-  FrameLogMap::iterator it = frame_map_.find(event);
-  if (it == frame_map_.end()) {
-    // Create new entry.
-    FrameLogData data(clock_);
-    data.InsertWithSize(rtp_timestamp, frame_id, size);
-    frame_map_.insert(std::make_pair(event, &data));
-  } else {
-    // Insert to existing entry.
-    it->second->InsertWithSize(rtp_timestamp, frame_id, size);
-  }
-}
-
-void Logging::InsertFrameEventWithDelay(CastLoggingEvent event,
-                                        uint32 rtp_timestamp,
-                                        uint32 frame_id,
-                                        base::TimeDelta delay) {
-  // Is this a new event?
-  FrameLogMap::iterator it = frame_map_.find(event);
-  if (it == frame_map_.end()) {
-    // Create new entry.
-    FrameLogData data(clock_);
-    data.InsertWithDelay(rtp_timestamp, frame_id, delay);
-    frame_map_.insert(std::make_pair(event, &data));
-  } else {
-    // Insert to existing entry.
-    it->second->InsertWithDelay(rtp_timestamp, frame_id, delay);
-  }
-}
-
-void Logging::InsertPacketEvent(CastLoggingEvent event,
-                                uint32 rtp_timestamp,
-                                uint32 frame_id,
-                                uint16 packet_id,
-                                uint16 max_packet_id,
-                                int size) {
-  // Is this a new event?
-  PacketLogMap::iterator it = packet_map_.find(event);
-  if (it == packet_map_.end()) {
-    // Create new entry.
-    PacketLogData data(clock_);
-    data.Insert(rtp_timestamp, frame_id, packet_id, max_packet_id, size);
-    packet_map_.insert(std::make_pair(event, &data));
-  } else {
-    // Insert to existing entry.
-    it->second->Insert(rtp_timestamp, frame_id, packet_id, max_packet_id, size);
-  }
-}
-
-void Logging::InsertGenericEvent(CastLoggingEvent event, int value) {
-  // Is this a new event?
-  GenericLogMap::iterator it = generic_map_.find(event);
-  if (it == generic_map_.end()) {
-    // Create new entry.
-    GenericLogData data(clock_);
-    data.Insert(value);
-    generic_map_.insert(std::make_pair(event, &data));
-  } else {
-    // Insert to existing entry.
-    it->second->Insert(value);
-  }
-}
-
-void Logging::Reset() {
-  frame_map_.clear();
-  packet_map_.clear();
-  generic_map_.clear();
-}
-}  // namespace cast
-}  // namespace media
-
diff --git a/media/cast/logging/logging.h b/media/cast/logging/logging.h
deleted file mode 100644
index f327a6f..0000000
--- a/media/cast/logging/logging.h
+++ /dev/null
@@ -1,92 +0,0 @@
-// Copyright 2013 The Chromium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style license that can be
-// found in the LICENSE file.
-
-#ifndef MEDIA_CAST_LOGGING_LOGGING_H_
-#define MEDIA_CAST_LOGGING_LOGGING_H_
-
-// Generic class that handles event logging for the cast library.
-// Logging has three possible forms:
-// 1. [default] Raw data accessible by the application.
-// 2. [optional] UMA stats.
-// 3. [optional] Tracing.
-
-#include <map>
-#include <string>
-#include <vector>
-
-#include "base/basictypes.h"
-#include "base/memory/linked_ptr.h"
-#include "base/memory/weak_ptr.h"
-#include "base/threading/non_thread_safe.h"
-#include "base/time/tick_clock.h"
-#include "base/time/time.h"
-#include "media/cast/logging/logging_defines.h"
-#include "media/cast/logging/logging_internal.h"
-
-namespace media {
-namespace cast {
-
-// Store all log types in a map based on the event.
-typedef std::map<CastLoggingEvent, linked_ptr<FrameLogData> > FrameLogMap;
-typedef std::map<CastLoggingEvent, linked_ptr<PacketLogData> > PacketLogMap;
-typedef std::map<CastLoggingEvent, linked_ptr<GenericLogData> > GenericLogMap;
-
-
-// This class is not thread safe, and should only be called from the main
-// thread.
-class Logging : public base::NonThreadSafe,
-                public base::SupportsWeakPtr<Logging> {
- public:
-  // When tracing is enabled - all events will be added to the trace.
-  explicit Logging(base::TickClock* clock);
-  ~Logging();
-  // Inform of new event: three types of events: frame, packets and generic.
-  // Frame events can be inserted with different parameters.
-  void InsertFrameEvent(CastLoggingEvent event,
-                        uint32 rtp_timestamp,
-                        uint32 frame_id);
-  // Size - Inserting the size implies that this is an encoded frame.
-  void InsertFrameEventWithSize(CastLoggingEvent event,
-                                uint32 rtp_timestamp,
-                                uint32 frame_id,
-                                int frame_size);
-  // Render/playout delay
-  void InsertFrameEventWithDelay(CastLoggingEvent event,
-                                 uint32 rtp_timestamp,
-                                 uint32 frame_id,
-                                 base::TimeDelta delay);
-
-  // Insert a packet event.
-  void InsertPacketEvent(CastLoggingEvent event,
-                         uint32 rtp_timestamp,
-                         uint32 frame_id,
-                         uint16 packet_id,
-                         uint16 max_packet_id,
-                         int size);
-
-  void InsertGenericEvent(CastLoggingEvent event, int value);
-
-  // Get log data.
-  void GetRawFrameData(FrameLogMap frame_data);
-  void GetRawPacketData(PacketLogMap packet_data);
-  void GetRawGenericData(GenericLogMap generic_data);
-
-  // Reset all log data (not flags).
-  void Reset();
-
- private:
-  base::WeakPtrFactory<Logging> weak_factory_;
-  base::TickClock* const clock_;  // Not owned by this class.
-  FrameLogMap frame_map_;
-  PacketLogMap packet_map_;
-  GenericLogMap generic_map_;
-
-  DISALLOW_COPY_AND_ASSIGN(Logging);
-};
-
-}  // namespace cast
-}  // namespace media
-
-#endif  // MEDIA_CAST_LOGGING_LOGGING_H_
-
diff --git a/media/cast/logging/logging_defines.h b/media/cast/logging/logging_defines.h
index cdf9069..5a7bca15 100644
--- a/media/cast/logging/logging_defines.h
+++ b/media/cast/logging/logging_defines.h
@@ -15,6 +15,8 @@
 namespace media {
 namespace cast {
 
+static const uint32 kFrameIdUnknown = 0xFFFF;
+
 struct CastLoggingConfig {
   CastLoggingConfig();
   ~CastLoggingConfig();
diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc
index 97c9277..16117b0 100644
--- a/media/cast/logging/logging_impl.cc
+++ b/media/cast/logging/logging_impl.cc
@@ -5,6 +5,7 @@
 #include "base/debug/trace_event.h"
 #include "base/metrics/histogram.h"
 #include "media/cast/logging/logging_impl.h"
+#include "net/base/big_endian.h"
 
 namespace media {
 namespace cast {
@@ -76,6 +77,27 @@ void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event,
   }
 }
 
+void LoggingImpl::InsertPacketListEvent(CastLoggingEvent event,
+                                        const PacketList& packets) {
+  DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
+  for (unsigned int i = 0; i < packets.size(); ++i) {
+    const Packet& packet = packets[i];
+    // Parse basic properties.
+    uint32 rtp_timestamp;
+    uint16 packet_id, max_packet_id;
+    const uint8* packet_data = &packet[0];
+    net::BigEndianReader big_endian_reader(packet_data + 4, 4);
+    big_endian_reader.ReadU32(&rtp_timestamp);
+    net::BigEndianReader cast_big_endian_reader(packet_data + 12 + 2, 4);
+    cast_big_endian_reader.ReadU16(&packet_id);
+    cast_big_endian_reader.ReadU16(&max_packet_id);
+    // rtp_timestamp is enough - no need for frame_id as well.
+    InsertPacketEvent(event, rtp_timestamp, kFrameIdUnknown, packet_id,
+                      max_packet_id, packet.size());
+  }
+
+}
+
 void LoggingImpl::InsertPacketEvent(CastLoggingEvent event,
                                     uint32 rtp_timestamp,
                                     uint32 frame_id,
diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h
index 628f346..6c2d863 100644
--- a/media/cast/logging/logging_impl.h
+++ b/media/cast/logging/logging_impl.h
@@ -12,6 +12,7 @@
 
 #include "base/memory/ref_counted.h"
 #include "base/task_runner.h"
+#include "media/cast/cast_config.h"
 #include "media/cast/logging/logging_defines.h"
 #include "media/cast/logging/logging_raw.h"
 #include "media/cast/logging/logging_stats.h"
@@ -19,7 +20,6 @@
 namespace media {
 namespace cast {
 
-static const int kFrameIdUnknown = -1;
 // Should only be called from the main thread.
 class LoggingImpl : public base::NonThreadSafe {
  public:
@@ -40,6 +40,8 @@ class LoggingImpl : public base::NonThreadSafe {
                                  uint32 rtp_timestamp,
                                  uint32 frame_id,
                                  base::TimeDelta delay);
+  void InsertPacketListEvent(CastLoggingEvent event, const PacketList& packets);
+
   void InsertPacketEvent(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 0fd0ae17..93a65f0 100644
--- a/media/cast/logging/logging_raw.cc
+++ b/media/cast/logging/logging_raw.cc
@@ -51,7 +51,7 @@ void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event,
                                       uint32 frame_id,
                                       uint32 rtp_timestamp) {
   // Is this a new event?
-  FrameRawMap::iterator it = frame_map_.find(event);
+  FrameRawMap::iterator it = frame_map_.find(rtp_timestamp);
   if (it == frame_map_.end()) {
     // Create a new map entry.
     FrameEvent info;
@@ -64,11 +64,9 @@ void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event,
     it->second.timestamp.push_back(clock_->NowTicks());
     it->second.type.push_back(event);
     // Do we have a valid frame_id?
-    // We don't always have it to begin with.
-    // TODO(mikhal): Switch frame_id to int when the fix gets in.
-    // This is currently illegal, as frame_id is uint8, so commenting it out.
-    // if (it->second.frame_id == -1 && frame_id != -1)
-    //   it->second.frame_id = frame_id;
+    // Not all events have a valid frame id.
+    if (it->second.frame_id == kFrameIdUnknown && frame_id != kFrameIdUnknown)
+      it->second.frame_id = frame_id;
   }
 }
 
diff --git a/media/cast/pacing/paced_sender.cc b/media/cast/pacing/paced_sender.cc
index cc53075..af13d3a 100644
--- a/media/cast/pacing/paced_sender.cc
+++ b/media/cast/pacing/paced_sender.cc
@@ -29,11 +29,15 @@ PacedSender::~PacedSender() {}
 
 bool PacedSender::SendPackets(const PacketList& packets) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
+  cast_environment_->Logging()->InsertPacketListEvent(kPacketSentToPacer,
+                                                      packets);
   return SendPacketsToTransport(packets, &packet_list_);
 }
 
 bool PacedSender::ResendPackets(const PacketList& packets) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
+  cast_environment_->Logging()->InsertPacketListEvent(kPacketRetransmited,
+                                                      packets);
   return SendPacketsToTransport(packets, &resend_packet_list_);
 }
 
@@ -64,6 +68,8 @@ bool PacedSender::SendPacketsToTransport(const PacketList& packets,
   packets_sent_in_burst_ += packets_to_send.size();
   if (packets_to_send.empty()) return true;
 
+  cast_environment_->Logging()->InsertPacketListEvent(kPacketSentToNetwork,
+                                                      packets);
   return transport_->SendPackets(packets_to_send);
 }
 
diff --git a/media/cast/rtcp/rtcp.cc b/media/cast/rtcp/rtcp.cc
index c0e144a..d5ee6e3 100644
--- a/media/cast/rtcp/rtcp.cc
+++ b/media/cast/rtcp/rtcp.cc
@@ -188,6 +188,8 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message,
 
   if (cast_message) {
     packet_type_flags |= RtcpSender::kRtcpCast;
+    cast_environment_->Logging()->InsertGenericEvent(kAckSent,
+        cast_message->ack_frame_id_);
   }
   if (receiver_log) {
     packet_type_flags |= RtcpSender::kRtcpReceiverLog;
diff --git a/media/cast/test/end2end_unittest.cc b/media/cast/test/end2end_unittest.cc
index c461f82..0a2e097 100644
--- a/media/cast/test/end2end_unittest.cc
+++ b/media/cast/test/end2end_unittest.cc
@@ -315,6 +315,11 @@ class TestReceiverVideoCallback :
   std::list<ExpectedVideoFrame> expected_frame_;
 };
 
+CastLoggingConfig EnableCastLoggingConfig() {
+  CastLoggingConfig config;
+  config.enable_data_collection = true;
+  return config;
+}
 // The actual test class, generate synthetic data for both audio and video and
 // send those through the sender and receiver and analyzes the result.
 class End2EndTest : public ::testing::Test {
@@ -323,7 +328,7 @@ class End2EndTest : public ::testing::Test {
       : task_runner_(new test::FakeTaskRunner(&testing_clock_)),
         cast_environment_(new CastEnvironment(&testing_clock_, task_runner_,
             task_runner_, task_runner_, task_runner_, task_runner_,
-            GetDefaultCastLoggingConfig())),
+            EnableCastLoggingConfig())),
         start_time_(),
         sender_to_receiver_(cast_environment_),
         receiver_to_sender_(cast_environment_),
@@ -875,6 +880,152 @@ TEST_F(End2EndTest, CryptoAudio) {
             test_receiver_audio_callback_->number_times_called());
 }
 
+// Video test without packet loss; This test is targeted at testing the logging
+// aspects of the end2end, but is basically equivalent to LoopNoLossPcm16.
+TEST_F(End2EndTest, VideoLogging) {
+  SetupConfig(kPcm16, 32000, false, 1);
+  Create();
+
+  int video_start = 1;
+  int i = 0;
+  for (; i < 1; ++i) {
+    base::TimeTicks send_time = testing_clock_.NowTicks();
+    test_receiver_video_callback_->AddExpectedResult(video_start,
+        video_sender_config_.width, video_sender_config_.height, send_time);
+
+    SendVideoFrame(video_start, send_time);
+    RunTasks(kFrameTimerMs);
+
+    frame_receiver_->GetRawVideoFrame(
+        base::Bind(&TestReceiverVideoCallback::CheckVideoFrame,
+            test_receiver_video_callback_));
+
+    video_start++;
+  }
+
+  // Basic tests.
+  RunTasks(2 * kFrameTimerMs + 1);  // Empty the receiver pipeline.
+  EXPECT_EQ(i, test_receiver_video_callback_->number_times_called());
+  // Logging tests.
+  LoggingImpl* logging = cast_environment_->Logging();
+
+  // Frame logging.
+
+  // Verify that all frames and all required events were logged.
+  FrameRawMap frame_raw_log = logging->GetFrameRawData();
+  // Every frame should have only one entry.
+  EXPECT_EQ(static_cast<unsigned int>(i), frame_raw_log.size());
+  FrameRawMap::const_iterator frame_it = frame_raw_log.begin();
+  // Choose a video frame, and verify that all events were logged.
+  std::vector<CastLoggingEvent> event_log = frame_it->second.type;
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kVideoFrameReceived)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kVideoFrameSentToEncoder)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kVideoFrameEncoded)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kVideoRenderDelay)) != event_log.end());
+  // TODO(mikhal): Plumb this one through.
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kVideoFrameDecoded)) == event_log.end());
+  // Verify that there were no other events logged with respect to this frame.
+  EXPECT_EQ(4u, event_log.size());
+
+  // Packet logging.
+  // Verify that all packet related events were logged.
+  PacketRawMap packet_raw_log = logging->GetPacketRawData();
+  // Every rtp_timestamp should have only one entry.
+  EXPECT_EQ(static_cast<unsigned int>(i), packet_raw_log.size());
+  PacketRawMap::const_iterator packet_it = packet_raw_log.begin();
+  // Choose a packet, and verify that all events were logged.
+  event_log = (++(packet_it->second.packet_map.begin()))->second.type;
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kPacketSentToPacer)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kPacketSentToNetwork)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kPacketReceived)) != event_log.end());
+  // Verify that there were no other events logged with respect to this frame.
+  EXPECT_EQ(3u, event_log.size());
+}
+
+// Audio test without packet loss; This test is targeted at testing the logging
+// aspects of the end2end, but is basically equivalent to LoopNoLossPcm16.
+TEST_F(End2EndTest, AudioLogging) {
+  SetupConfig(kPcm16, 32000, false, 1);
+  Create();
+
+  int audio_diff = kFrameTimerMs;
+  int i = 0;
+
+  for (; i < 10; ++i) {
+    int num_10ms_blocks = audio_diff / 10;
+    audio_diff -= num_10ms_blocks * 10;
+    base::TimeTicks send_time = testing_clock_.NowTicks();
+
+    scoped_ptr<AudioBus> audio_bus(audio_bus_factory_->NextAudioBus(
+        base::TimeDelta::FromMilliseconds(10) * num_10ms_blocks));
+
+    if (i != 0) {
+      // Due to the re-sampler and NetEq in the webrtc AudioCodingModule the
+      // first samples will be 0 and then slowly ramp up to its real amplitude;
+      // ignore the first frame.
+      test_receiver_audio_callback_->AddExpectedResult(
+          ToPcmAudioFrame(*audio_bus, audio_sender_config_.frequency),
+          num_10ms_blocks, send_time);
+    }
+
+    AudioBus* const audio_bus_ptr = audio_bus.get();
+    frame_input_->InsertAudio(audio_bus_ptr, send_time,
+        base::Bind(base::DoNothing));
+
+    RunTasks(kFrameTimerMs);
+    audio_diff += kFrameTimerMs;
+
+    if (i == 0) {
+      frame_receiver_->GetRawAudioFrame(num_10ms_blocks,
+          audio_sender_config_.frequency,
+          base::Bind(&TestReceiverAudioCallback::IgnoreAudioFrame,
+              test_receiver_audio_callback_));
+    } else {
+      frame_receiver_->GetRawAudioFrame(num_10ms_blocks,
+          audio_sender_config_.frequency,
+          base::Bind(&TestReceiverAudioCallback::CheckPcmAudioFrame,
+              test_receiver_audio_callback_));
+    }
+  }
+
+  // Basic tests.
+  RunTasks(2 * kFrameTimerMs + 1);  // Empty the receiver pipeline.
+  //EXPECT_EQ(i - 1, test_receiver_audio_callback_->number_times_called());
+  EXPECT_EQ(i - 1, test_receiver_audio_callback_->number_times_called());
+  // Logging tests.
+  LoggingImpl* logging = cast_environment_->Logging();
+  // Verify that all frames and all required events were logged.
+  FrameRawMap frame_raw_log = logging->GetFrameRawData();
+  // TODO(mikhal): Results are wrong. Need to resolve passing/calculation of
+  // rtp_timestamp for audio for this to work.
+  // Should have logged both audio and video. Every frame should have only one
+  // entry.
+  //EXPECT_EQ(static_cast<unsigned int>(i - 1), frame_raw_log.size());
+  FrameRawMap::const_iterator frame_it = frame_raw_log.begin();
+  // Choose a video frame, and verify that all events were logged.
+  std::vector<CastLoggingEvent> event_log = frame_it->second.type;
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kAudioFrameReceived)) != event_log.end());
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kAudioFrameEncoded)) != event_log.end());
+  // EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+  //              kAudioPlayoutDelay)) != event_log.end());
+  // TODO(mikhal): Plumb this one through.
+  EXPECT_TRUE((std::find(event_log.begin(), event_log.end(),
+               kAudioFrameDecoded)) == event_log.end());
+  // Verify that there were no other events logged with respect to this frame.
+  EXPECT_EQ(2u, event_log.size());
+}
+
+
 // TODO(pwestin): Add repeatable packet loss test.
 // TODO(pwestin): Add test for misaligned send get calls.
 // TODO(pwestin): Add more tests that does not resample.
diff --git a/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc b/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc
index 84d4fa9..bf56b0a 100644
--- a/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc
+++ b/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc
@@ -12,6 +12,13 @@
 namespace media {
 namespace cast {
 
+void LogFrameDecodedEvent(CastEnvironment* const cast_environment,
+                          uint32 frame_id) {
+// TODO(mikhal): Sort out passing of rtp_timestamp.
+// cast_environment->Logging()->InsertFrameEvent(kVideoFrameDecoded,
+//      0, frame_id);
+}
+
 Vp8Decoder::Vp8Decoder(int number_of_cores,
                        scoped_refptr<CastEnvironment> cast_environment)
     : decoder_(new vpx_dec_ctx_t()),
@@ -84,13 +91,15 @@ bool Vp8Decoder::Decode(const EncodedVideoFrame* encoded_frame,
   memcpy(decoded_frame->v_plane.data, img->planes[VPX_PLANE_V],
          decoded_frame->v_plane.length);
 
-  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameDecoded,
-      kFrameIdUnknown, encoded_frame->frame_id);
+  // Log:: Decoding complete (should be called from the main thread).
+  cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(
+      LogFrameDecodedEvent, cast_environment_,encoded_frame->frame_id));
   VLOG(1) << "Decoded frame " << frame_id_int;
 
   // Frame decoded - return frame to the user via callback.
   cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
-      base::Bind(frame_decoded_cb, base::Passed(&decoded_frame), render_time));
+      base::Bind(frame_decoded_cb, base::Passed(&decoded_frame),
+                 render_time));
 
   return true;
 }
diff --git a/media/cast/video_receiver/video_receiver.cc b/media/cast/video_receiver/video_receiver.cc
index 19f98e8..98bed1f 100644
--- a/media/cast/video_receiver/video_receiver.cc
+++ b/media/cast/video_receiver/video_receiver.cc
@@ -151,8 +151,7 @@ void VideoReceiver::GetRawVideoFrame(
     const VideoFrameDecodedCallback& callback) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   GetEncodedVideoFrame(base::Bind(&VideoReceiver::DecodeVideoFrame,
-                                  weak_factory_.GetWeakPtr(),
-                                  callback));
+                                  base::Unretained(this), callback));
 }
 
 // Called when we have a frame to decode.
@@ -163,10 +162,8 @@ void VideoReceiver::DecodeVideoFrame(
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   // Hand the ownership of the encoded frame to the decode thread.
   cast_environment_->PostTask(CastEnvironment::VIDEO_DECODER, FROM_HERE,
-      base::Bind(&VideoReceiver::DecodeVideoFrameThread,
-                 base::Unretained(this),
-                 base::Passed(&encoded_frame),
-                 render_time, callback));
+      base::Bind(&VideoReceiver::DecodeVideoFrameThread, base::Unretained(this),
+                 base::Passed(&encoded_frame), render_time, callback));
 }
 
 // Utility function to run the decoder on a designated decoding thread.
@@ -178,7 +175,7 @@ void VideoReceiver::DecodeVideoFrameThread(
   DCHECK(video_decoder_);
 
   if (!(video_decoder_->DecodeVideoFrame(encoded_frame.get(), render_time,
-                                        frame_decoded_callback))) {
+        frame_decoded_callback))) {
     // This will happen if we decide to decode but not show a frame.
     cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
         base::Bind(&VideoReceiver::GetRawVideoFrame, base::Unretained(this),
@@ -251,10 +248,10 @@ bool VideoReceiver::PullEncodedVideoFrame(uint32 rtp_timestamp,
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   *render_time = GetRenderTime(now, rtp_timestamp);
-  base::TimeDelta diff = now - *render_time;
 
-  cast_environment_->Logging()->InsertFrameEvent(kVideoRenderDelay,
-      rtp_timestamp, diff.InMilliseconds());
+  // TODO(mikhal): Store actual render time and not diff.
+  cast_environment_->Logging()->InsertFrameEventWithDelay(kVideoRenderDelay,
+      rtp_timestamp, (*encoded_frame)->frame_id, now - *render_time);
 
   // Minimum time before a frame is due to be rendered before we pull it for
   // decode.
diff --git a/media/cast/video_sender/video_encoder.cc b/media/cast/video_sender/video_encoder.cc
index 5c30ca7..46d82dd 100644
--- a/media/cast/video_sender/video_encoder.cc
+++ b/media/cast/video_sender/video_encoder.cc
@@ -8,10 +8,17 @@
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
 #include "media/base/video_frame.h"
+#include "media/cast/cast_defines.h"
 
 namespace media {
 namespace cast {
 
+void LogFrameEncodedEvent(CastEnvironment* const cast_environment,
+                          const base::TimeTicks& capture_time) {
+  cast_environment->Logging()->InsertFrameEvent(kVideoFrameEncoded,
+      GetVideoRtpTimestamp(capture_time), kFrameIdUnknown);
+}
+
 VideoEncoder::VideoEncoder(scoped_refptr<CastEnvironment> cast_environment,
                            const VideoSenderConfig& video_config,
                            uint8 max_unacked_frames)
@@ -46,6 +53,8 @@ bool VideoEncoder::EncodeVideoFrame(
     return false;
   }
 
+  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameSentToEncoder,
+      GetVideoRtpTimestamp(capture_time), kFrameIdUnknown);
   cast_environment_->PostTask(CastEnvironment::VIDEO_ENCODER, FROM_HERE,
       base::Bind(&VideoEncoder::EncodeVideoFrameEncoderThread,
                  base::Unretained(this), video_frame, capture_time,
@@ -62,6 +71,7 @@ void VideoEncoder::EncodeVideoFrameEncoderThread(
     const CodecDynamicConfig& dynamic_config,
     const FrameEncodedCallback& frame_encoded_callback,
     const base::Closure frame_release_callback) {
+  DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::VIDEO_ENCODER));
   if (dynamic_config.key_frame_requested) {
     vp8_encoder_->GenerateKeyFrame();
   }
@@ -69,12 +79,11 @@ void VideoEncoder::EncodeVideoFrameEncoderThread(
       dynamic_config.latest_frame_id_to_reference);
   vp8_encoder_->UpdateRates(dynamic_config.bit_rate);
 
-  uint32 rtp_timestamp = GetVideoRtpTimestamp(capture_time);
-  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameSentToEncoder,
-      rtp_timestamp, kFrameIdUnknown);
   scoped_ptr<EncodedVideoFrame> encoded_frame(new EncodedVideoFrame());
   bool retval = vp8_encoder_->Encode(video_frame, encoded_frame.get());
 
+  cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
+      base::Bind(LogFrameEncodedEvent, cast_environment_, capture_time));
   // We are done with the video frame release it.
   cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
                               frame_release_callback);
@@ -87,8 +96,6 @@ void VideoEncoder::EncodeVideoFrameEncoderThread(
     VLOG(1) << "Encoding resulted in an empty frame";
     return;
   }
-  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameEncoded,
-      rtp_timestamp, kFrameIdUnknown);
   cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
       base::Bind(frame_encoded_callback,
           base::Passed(&encoded_frame), capture_time));
diff --git a/media/cast/video_sender/video_encoder.h b/media/cast/video_sender/video_encoder.h
index 4140bfc..f8415f6 100644
--- a/media/cast/video_sender/video_encoder.h
+++ b/media/cast/video_sender/video_encoder.h
@@ -67,6 +67,8 @@ class VideoEncoder : public VideoEncoderController {
   virtual int NumberOfSkippedFrames() const OVERRIDE;
 
  private:
+  friend class base::RefCountedThreadSafe<VideoEncoder>;
+
   const VideoSenderConfig video_config_;
   scoped_refptr<CastEnvironment> cast_environment_;
   scoped_ptr<Vp8Encoder> vp8_encoder_;