Fix the timestamp generation for webrtc native log.

chrome/browser/media/webrtc_logging_handler_host.cc

 // 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 "chrome/browser/media/webrtc_logging_handler_host.h"
 
+#include <iomanip>
+#include <sstream>
 #include <string>
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/cpu.h"
 #include "base/file_util.h"
 #include "base/logging.h"
 #include "base/prefs/pref_service.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
 #include "base/time/time.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/chromeos/settings/cros_settings.h"
 #include "chrome/browser/media/webrtc_log_list.h"
 #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"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/content_browser_client.h"
 #include "content/public/browser/gpu_data_manager.h"
 #include "content/public/browser/render_process_host.h"
 #include "gpu/config/gpu_info.h"
 #include "net/base/address_family.h"
 #include "net/url_request/url_request_context_getter.h"
@@ skipping 72 matching lines @@
   // Remove last '\n'.
   message->resize(message->size() - 1);
 }
 
 }  // namespace
 
 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_);
 }
 
 WebRtcLoggingHandlerHost::~WebRtcLoggingHandlerHost() {}
 
 void WebRtcLoggingHandlerHost::SetMetaData(
     const MetaDataMap& meta_data,
     const GenericDoneCallback& callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   DCHECK(!callback.is_null());
@@ skipping 84 matching lines @@
   log_buffer_.reset();
   logging_state_ = CLOSED;
   FireGenericDoneCallback(&discard_callback, true, "");
 }
 
 void WebRtcLoggingHandlerHost::LogMessage(const std::string& message) {
   BrowserThread::PostTask(
       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() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   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,
           base::Bind(&WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists,
                      this),
           base::Bind(&WebRtcLoggingHandlerHost::TriggerUploadLog, this));
     } else {
       g_browser_process->webrtc_log_uploader()->LoggingStoppedDontUpload();
     }
   }
   content::BrowserMessageFilter::OnChannelClosing();
 }
 
 void WebRtcLoggingHandlerHost::OnDestruct() const {
   BrowserThread::DeleteOnIOThread::Destruct(this);
 }
 
 bool WebRtcLoggingHandlerHost::OnMessageReceived(const IPC::Message& message,
                                                  bool* message_was_ok) {
   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)
   IPC_END_MESSAGE_MAP_EX()
 
   return handled;
 }
 
 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() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   if (logging_state_ != STOPPING) {
     // If an out-of-order response is received, stop_callback_ may be invalid,
     // and must not be invoked.
     DLOG(ERROR) << "OnLoggingStoppedInRenderer invoked in state "
                 << logging_state_;
     BadMessageReceived();
     return;
   }
+  logging_started_time_ms_ = 0;
   logging_state_ = STOPPED;
   FireGenericDoneCallback(&stop_callback_, true, "");
 }
 
 void WebRtcLoggingHandlerHost::StartLoggingIfAllowed() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   if (!g_browser_process->webrtc_log_uploader()->ApplyForStartLogging()) {
     logging_state_ = CLOSED;
       FireGenericDoneCallback(
           &start_callback_, false, "Cannot start, maybe the maximum number of "
@@ skipping 97 matching lines @@
     LogToCircularBuffer("Name: " + it->friendly_name + ", Address: " +
                         IPAddressToSensitiveString(it->address));
   }
 
   NotifyLoggingStarted();
 }
 
 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, "");
 }
 
 void WebRtcLoggingHandlerHost::LogToCircularBuffer(const std::string& message) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   DCHECK(circular_buffer_.get());
   circular_buffer_->Write(message.c_str(), message.length());
   const char eol = '\n';
   circular_buffer_->Write(&eol, 1);
@@ skipping 39 matching lines @@
 void WebRtcLoggingHandlerHost::FireGenericDoneCallback(
     GenericDoneCallback* callback, bool success,
     const std::string& error_message) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   DCHECK(!(*callback).is_null());
   content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
                                    base::Bind(*callback, success,
                                               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();
+}