Write "logout-started" event on next boot.

chrome/browser/chromeos/boot_times_loader.cc

 // Copyright (c) 2012 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/chromeos/boot_times_loader.h"
 
 #include <vector>
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/file_util.h"
 #include "base/files/file_path.h"
+#include "base/json/json_reader.h"
+#include "base/json/json_writer.h"
 #include "base/lazy_instance.h"
 #include "base/location.h"
 #include "base/message_loop/message_loop.h"
 #include "base/message_loop/message_loop_proxy.h"
 #include "base/metrics/histogram.h"
+#include "base/prefs/pref_service.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/chrome_notification_types.h"
 #include "chrome/browser/chromeos/login/auth/authentication_notification_details.h"
 #include "chrome/browser/chromeos/login/users/user_manager.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_iterator.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
 #include "chrome/common/chrome_switches.h"
+#include "chrome/common/pref_names.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/navigation_controller.h"
 #include "content/public/browser/notification_service.h"
 #include "content/public/browser/render_widget_host_view.h"
 #include "content/public/browser/web_contents.h"
 
 using content::BrowserThread;
 using content::NavigationController;
 using content::RenderWidgetHost;
 using content::RenderWidgetHostView;
 using content::WebContents;
 
 namespace {
 
+const char kUptime[] = "uptime";
+const char kDisk[] = "disk";
+
 RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
   WebContents* web_contents = tab->GetWebContents();
   if (web_contents) {
     RenderWidgetHostView* render_widget_host_view =
         web_contents->GetRenderWidgetHostView();
     if (render_widget_host_view)
       return render_widget_host_view->GetRenderWidgetHost();
   }
   return NULL;
 }
 
 const std::string GetTabUrl(RenderWidgetHost* rwh) {
   RenderWidgetHostView* rwhv = rwh->GetView();
   for (chrome::BrowserIterator it; !it.done(); it.Next()) {
     Browser* browser = *it;
     for (int i = 0, tab_count = browser->tab_strip_model()->count();
          i < tab_count;
          ++i) {
       WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
       if (tab->GetRenderWidgetHostView() == rwhv) {
         return tab->GetLastCommittedURL().spec();
       }
     }
   }
   return std::string();
 }
 
+// Appends the given buffer into the file. Returns the number of bytes
+// written, or -1 on error.
+// TODO(satorux): Move this to file_util.
+int AppendFile(const base::FilePath& file_path, const char* data, int size) {
+  FILE* file = base::OpenFile(file_path, "a");
+  if (!file)
+    return -1;
+
+  const int num_bytes_written = fwrite(data, 1, size, file);
+  base::CloseFile(file);
+  return num_bytes_written;
+}
+
 }  // namespace
 
 namespace chromeos {
 
 #define FPL(value) FILE_PATH_LITERAL(value)
 
 // Dir uptime & disk logs are located in.
 static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
 // Dir log{in,out} logs are located in.
 static const base::FilePath::CharType kLoginLogPath[] =
@@ skipping 22 matching lines @@
 
 // Name of file collecting login times.
 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
 
 // Name of file collecting logout times.
 static const char kLogoutTimes[] = "logout-times";
 
 static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
     LAZY_INSTANCE_INITIALIZER;
 
-BootTimesLoader::BootTimesLoader()
-    : backend_(new Backend()),
-      have_registered_(false),
-      login_done_(false),
-      restart_requested_(false) {
-  login_time_markers_.reserve(30);
-  logout_time_markers_.reserve(30);
+// static
+BootTimesLoader::Stats BootTimesLoader::Stats::GetCurrentStats() {
+  const base::FilePath kProcUptime(FPL("/proc/uptime"));
+  const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
+  Stats stats;
+  // Callers of this method expect synchronous behavior.
+  // It's safe to allow IO here, because only virtual FS are accessed.
+  base::ThreadRestrictions::ScopedAllowIO allow_io;
+  base::ReadFileToString(kProcUptime, &stats.uptime_);
+  base::ReadFileToString(kDiskStat, &stats.disk_);
+  return stats;
 }
 
-BootTimesLoader::~BootTimesLoader() {}
+std::string BootTimesLoader::Stats::SerializeToString() const {
+  if (uptime_.empty() || disk_.empty())
+    return std::string();
+  base::DictionaryValue dictionary;
+  dictionary.SetString(kUptime, uptime_);
+  dictionary.SetString(kDisk, disk_);
+
+  std::string result;
+  if (!base::JSONWriter::Write(&dictionary, &result)) {
+    LOG(WARNING) << "BootTimesLoader::Stats::SerializeToString(): failed.";
+    return result;

[stevenjb, 2014/06/02 19:11:38]

nit: don't return here ('return result' occurs below which was what I meant to
suggest), or explicitly return std::string() as before if you prefer.

[Alexander Alekseev, 2014/06/02 19:18:45]

Done.

+  }
+
+  return result;
+}
 
 // static
-BootTimesLoader* BootTimesLoader::Get() {
-  return g_boot_times_loader.Pointer();
+BootTimesLoader::Stats BootTimesLoader::Stats::DeserializeFromString(
+    const std::string& source) {
+  if (source.empty())
+    return Stats();
+
+  scoped_ptr<base::Value> value(base::JSONReader::Read(source));
+  base::DictionaryValue* dictionary;
+  if (!value || !value->GetAsDictionary(&dictionary)) {
+    LOG(ERROR) << "BootTimesLoader::Stats::DeserializeFromString(): not a "
+                  "dictionary: '" << source << "'";
+    return Stats();
+  }
+
+  Stats result;
+  if (!dictionary->GetString(kUptime, &result.uptime_) ||
+      !dictionary->GetString(kDisk, &result.disk_)) {
+    LOG(ERROR)
+        << "BootTimesLoader::Stats::DeserializeFromString(): format error: '"
+        << source << "'";
+    return Stats();

[stevenjb, 2014/06/02 19:11:38]

nit: Here also, explicit return isn't necessary.

[Alexander Alekseev, 2014/06/02 19:18:45]

It is dangerous, because if first call succeeds, but second fails, the returned
object will be half-initialized.

[stevenjb, 2014/06/02 19:26:33]

Good point, looks good.

+  }
+
+  return result;
 }
 
-// Appends the given buffer into the file. Returns the number of bytes
-// written, or -1 on error.
-// TODO(satorux): Move this to file_util.
-static int AppendFile(const base::FilePath& file_path,
-                      const char* data,
-                      int size) {
-  FILE* file = base::OpenFile(file_path, "a");
-  if (!file) {
-    return -1;
-  }
-  const int num_bytes_written = fwrite(data, 1, size, file);
-  base::CloseFile(file);
-  return num_bytes_written;
+bool BootTimesLoader::Stats::UptimeDouble(double* result) const {
+  std::string uptime = uptime_;
+  const size_t space_at = uptime.find_first_of(' ');
+  if (space_at == std::string::npos)
+    return false;
+
+  uptime.resize(space_at);
+
+  if (base::StringToDouble(uptime, result))
+    return true;
+
+  return false;
 }
 
-static void RecordStatsDelayed(const base::FilePath::StringType& name,
-                               const std::string& uptime,
-                               const std::string& disk) {
+void BootTimesLoader::Stats::RecordStats(const std::string& name) const {
+  BrowserThread::PostBlockingPoolTask(
+      FROM_HERE,
+      base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
+                 base::Owned(new Stats(*this)),
+                 name));
+}
+
+void BootTimesLoader::Stats::RecordStatsWithCallback(
+    const std::string& name,
+    const base::Closure& callback) const {
+  BrowserThread::PostBlockingPoolTaskAndReply(
+      FROM_HERE,
+      base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
+                 base::Owned(new Stats(*this)),
+                 name),
+      callback);
+}
+
+void BootTimesLoader::Stats::RecordStatsImpl(
+    const base::FilePath::StringType& name) const {
+  DCHECK(content::BrowserThread::GetBlockingPool()->RunsTasksOnCurrentThread());
+
   const base::FilePath log_path(kLogPath);
   const base::FilePath uptime_output =
       log_path.Append(base::FilePath(kUptimePrefix + name));
   const base::FilePath disk_output =
       log_path.Append(base::FilePath(kDiskPrefix + name));
 
   // Append numbers to the files.
-  AppendFile(uptime_output, uptime.data(), uptime.size());
-  AppendFile(disk_output, disk.data(), disk.size());
+  AppendFile(uptime_output, uptime_.data(), uptime_.size());
+  AppendFile(disk_output, disk_.data(), disk_.size());
+}
+
+BootTimesLoader::BootTimesLoader()
+    : backend_(new Backend()),
+      have_registered_(false),
+      login_done_(false),
+      restart_requested_(false) {
+  login_time_markers_.reserve(30);
+  logout_time_markers_.reserve(30);
+}
+
+BootTimesLoader::~BootTimesLoader() {
 }
 
 // static
+BootTimesLoader* BootTimesLoader::Get() {
+  return g_boot_times_loader.Pointer();
+}
+
+// static
 void BootTimesLoader::WriteTimes(
     const std::string base_name,
     const std::string uma_name,
     const std::string uma_prefix,
     std::vector<TimeMarker> login_times) {
   const int kMinTimeMillis = 1;
   const int kMaxTimeMillis = 30000;
   const int kNumBuckets = 100;
   const base::FilePath log_path(kLoginLogPath);
 
@@ skipping 87 matching lines @@
   // has already been terminated.
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
 
   WriteTimes(kLogoutTimes,
              (restart_requested_ ? kUmaRestart : kUmaLogout),
              kUmaLogoutPrefix,
              logout_time_markers_);
 }
 
-void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
-  BrowserThread::PostTask(
-      BrowserThread::FILE, FROM_HERE,
-      base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
+// static
+void BootTimesLoader::ClearLogoutStartedLastPreference() {
+  PrefService* local_state = g_browser_process->local_state();
+  local_state->ClearPref(prefs::kLogoutStartedLast);
 }
 
-BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
-  const base::FilePath kProcUptime(FPL("/proc/uptime"));
-  const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
-  Stats stats;
-  base::ThreadRestrictions::ScopedAllowIO allow_io;
-  base::ReadFileToString(kProcUptime, &stats.uptime);
-  base::ReadFileToString(kDiskStat, &stats.disk);
-  return stats;
+void BootTimesLoader::OnChromeProcessStart() {
+  PrefService* local_state = g_browser_process->local_state();
+  const std::string logout_started_last_str =
+      local_state->GetString(prefs::kLogoutStartedLast);
+  if (logout_started_last_str.empty())
+    return;
+
+  // Note that kLogoutStartedLast is not cleared on format error to stay in
+  // logs in case of other fatal system errors.
+
+  const Stats logout_started_last_stats =
+      Stats::DeserializeFromString(logout_started_last_str);
+  if (logout_started_last_stats.uptime().empty())
+    return;
+
+  double logout_started_last;
+  double uptime;
+  if (!logout_started_last_stats.UptimeDouble(&logout_started_last) ||
+      !Stats::GetCurrentStats().UptimeDouble(&uptime)) {
+    return;
+  }
+
+  if (logout_started_last >= uptime) {
+    // Reboot happened.
+    ClearLogoutStartedLastPreference();
+    return;
+  }
+
+  // Write /tmp/uptime-logout-started as well.
+  const char kLogoutStarted[] = "logout-started";
+  logout_started_last_stats.RecordStatsWithCallback(
+      kLogoutStarted,
+      base::Bind(&BootTimesLoader::ClearLogoutStartedLastPreference));
+}
+
+void BootTimesLoader::OnLogoutStarted(PrefService* state) {
+  const std::string uptime = Stats::GetCurrentStats().SerializeToString();
+  if (!uptime.empty())
+    state->SetString(prefs::kLogoutStartedLast, uptime);
 }
 
 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
-  RecordStats(name, GetCurrentStats());
+  Stats::GetCurrentStats().RecordStats(name);
 }
 
 void BootTimesLoader::SaveChromeMainStats() {
-  chrome_main_stats_ = GetCurrentStats();
+  chrome_main_stats_ = Stats::GetCurrentStats();
 }
 
 void BootTimesLoader::RecordChromeMainStats() {
-  RecordStats(kChromeMain, chrome_main_stats_);
+  chrome_main_stats_.RecordStats(kChromeMain);
 }
 
 void BootTimesLoader::RecordLoginAttempted() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   if (login_done_)
     return;
 
   login_time_markers_.clear();
   AddLoginTimeMarker("LoginStarted", false);
   if (!have_registered_) {
@@ skipping 94 matching lines @@
           GetRenderWidgetHost(&web_contents->GetController());
       render_widget_hosts_loading_.erase(render_widget_host);
       break;
     }
     default:
       break;
   }
 }
 
 }  // namespace chromeos