Fix the timestamp generation for webrtc native log.

chrome/browser/media/webrtc_logging_handler_host.cc

Index: chrome/browser/media/webrtc_logging_handler_host.cc
diff --git a/chrome/browser/media/webrtc_logging_handler_host.cc b/chrome/browser/media/webrtc_logging_handler_host.cc
index e1919d2670c2bb17bd436916f522fb9ab448de55..83278e28a47872afa723c2eae76358b18e7d66d1 100644
--- a/chrome/browser/media/webrtc_logging_handler_host.cc
+++ b/chrome/browser/media/webrtc_logging_handler_host.cc
@@ -4,6 +4,8 @@
 
 #include "chrome/browser/media/webrtc_logging_handler_host.h"
 
+#include <iomanip>
+#include <sstream>
 #include <string>
 
 #include "base/bind.h"
@@ -21,7 +23,6 @@
 #include "chrome/browser/media/webrtc_log_uploader.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/common/chrome_switches.h"
-#include "chrome/common/media/webrtc_logging_messages.h"
 #include "chrome/common/partial_circular_buffer.h"
 #include "chrome/common/pref_names.h"
 #include "chromeos/settings/cros_settings_names.h"
@@ -114,7 +115,8 @@ WebRtcLoggingHandlerHost::WebRtcLoggingHandlerHost(Profile* profile)
     : BrowserMessageFilter(WebRtcLoggingMsgStart),
       profile_(profile),
       logging_state_(CLOSED),
-      upload_log_on_render_close_(false) {
+      upload_log_on_render_close_(false),
+      logging_started_time_ms_(0) {
   DCHECK(profile_);
 }
 
@@ -219,7 +221,11 @@ void WebRtcLoggingHandlerHost::LogMessage(const std::string& message) {
       BrowserThread::IO,
       FROM_HERE,
       base::Bind(
-          &WebRtcLoggingHandlerHost::AddLogMessageFromBrowser, this, message));
+          &WebRtcLoggingHandlerHost::AddLogMessageFromBrowser,
+          this,
+          base::Time::Now().ToInternalValue() /

[dcheng, 2014/04/01 23:35:19]

1) Shouldn't we be using base::TimeTicks? base::Time::Now() can jump backwards
or forwards.
2) Why not just use TimeTicks directly everywhere? I don't see the point in
converting to uint64 and dividing everywhere.

[jiayl, 2014/04/01 23:50:06]

We do want to use base::Time::Now(), because
1. we want to know the time elapsed if the machine power state is suspended,
while TimeTicks remains still in that case.
2. the log is used in combination with JS logging for our application, where JS
only knows the system time. 

[jiayl, 2014/04/02 00:38:06]

uint64 changed to base::Time.

+              base::Time::kMicrosecondsPerMillisecond,
+          message));
 }
 
 void WebRtcLoggingHandlerHost::OnChannelClosing() {
@@ -227,6 +233,7 @@ void WebRtcLoggingHandlerHost::OnChannelClosing() {
   if (logging_state_ == STARTED || logging_state_ == STOPPED) {
     if (upload_log_on_render_close_) {
       logging_state_ = STOPPED;
+      logging_started_time_ms_ = 0;
       content::BrowserThread::PostTaskAndReplyWithResult(
           content::BrowserThread::FILE,
           FROM_HERE,
@@ -249,7 +256,7 @@ bool WebRtcLoggingHandlerHost::OnMessageReceived(const IPC::Message& message,
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   bool handled = true;
   IPC_BEGIN_MESSAGE_MAP_EX(WebRtcLoggingHandlerHost, message, *message_was_ok)
-    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_AddLogMessage, OnAddLogMessage)
+    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_AddLogMessages, OnAddLogMessages)
     IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_LoggingStopped,
                         OnLoggingStoppedInRenderer)
     IPC_MESSAGE_UNHANDLED(handled = false)
@@ -259,16 +266,22 @@ bool WebRtcLoggingHandlerHost::OnMessageReceived(const IPC::Message& message,
 }
 
 void WebRtcLoggingHandlerHost::AddLogMessageFromBrowser(
-    const std::string& message) {
+    uint64 timestamp_ms, const std::string& message) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   if (logging_state_ == STARTED)
-    LogToCircularBuffer(message);
+    LogToCircularBuffer(FormatMessageWithTimestamp(timestamp_ms, message));
 }
 
-void WebRtcLoggingHandlerHost::OnAddLogMessage(const std::string& message) {
+void WebRtcLoggingHandlerHost::OnAddLogMessages(
+    const std::vector<WebRtcLoggingMessage>& messages) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
-  if (logging_state_ == STARTED || logging_state_ == STOPPING)
-    LogToCircularBuffer(message);
+  if (logging_state_ == STARTED || logging_state_ == STOPPING) {
+    for (size_t i = 0; i < messages.size(); ++i) {
+      LogToCircularBuffer(
+          FormatMessageWithTimestamp(messages[i].timestamp_ms,
+                                     messages[i].message));
+    }
+  }
 }
 
 void WebRtcLoggingHandlerHost::OnLoggingStoppedInRenderer() {
@@ -281,6 +294,7 @@ void WebRtcLoggingHandlerHost::OnLoggingStoppedInRenderer() {
     BadMessageReceived();
     return;
   }
+  logging_started_time_ms_ = 0;
   logging_state_ = STOPPED;
   FireGenericDoneCallback(&stop_callback_, true, "");
 }
@@ -398,6 +412,8 @@ void WebRtcLoggingHandlerHost::LogInitialInfoOnIOThread(
 void WebRtcLoggingHandlerHost::NotifyLoggingStarted() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   Send(new WebRtcLoggingMsg_StartLogging());
+  logging_started_time_ms_ = base::Time::Now().ToInternalValue() /
+      base::Time::kMicrosecondsPerMillisecond;;
   logging_state_ = STARTED;
   FireGenericDoneCallback(&start_callback_, true, "");
 }
@@ -457,3 +473,15 @@ void WebRtcLoggingHandlerHost::FireGenericDoneCallback(
                                               error_message));
   (*callback).Reset();
 }
+
+std::string WebRtcLoggingHandlerHost::FormatMessageWithTimestamp(
+    uint64 msg_created_time_ms, const std::string& message) {
+  uint64 interval_ms = msg_created_time_ms - logging_started_time_ms_;
+
+  std::ostringstream oss;

[dcheng, 2014/04/01 23:35:19]

We don't generally use streams except for logging. How come StringPrintf()
doesn't work here?

[jiayl, 2014/04/02 00:38:06]

Done.

+  oss << "[" << std::setfill('0') << std::setw(3)
+      << (interval_ms / 1000) << ":" << std::setw(3)
+      << (interval_ms % 1000) << std::setfill(' ') << "] "
+      << message;
+  return oss.str();
+}