Temporary verbose logs in StatisticsProvider

Add temporary verbose logging into implementation of StatisticsProvider
and related files, in order to be able to track down issues on
non-dev-mode Chrome OS devices.

Example log snippet after this CL:

  [WARNING:name_value_pairs_parser.cc(128)] Statistics wpsw_cur mentioned in /usr/bin/crossystem: 777073775F637572202020202020202020202020202020203D203120202020202020202020202020202020202020202020202020202020202023205B524F2F696E745D204669726D776172652077726974652070726F74656374206861726477617265207377697463682063757272656E7420706F736974696F6E
  [WARNING:statistics_provider.cc(321)] Finished loading statistics.
  [WARNING:device_status_collector.cc(2071)] Statistics wpsw_cur: 1
  [INFO:status_uploader.cc(216)] Starting status upload: has_device_status = 1 write_protect_switch = 1

This CL will need to be reverted once the root cause of the associated
bug (b/158252688) is found.

Bug: 1123153
Change-Id: If718299a8aa8fa7b991168f8a46cccf0bd24f45d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2382751
Commit-Queue: Maksim Ivanov <emaxx@chromium.org>
Reviewed-by: Pavol Marko <pmarko@chromium.org>
Reviewed-by: Igor <igorcov@chromium.org>
Cr-Commit-Position: refs/heads/master@{#804187}

chrome/browser/chromeos/policy/status_collector/device_status_collector.cc

@@ -2061,8 +2061,16 @@ bool DeviceStatusCollector::GetWriteProtectSwitch(
   if (!statistics_provider_->GetMachineStatistic(
           chromeos::system::kFirmwareWriteProtectCurrentKey,
           &firmware_write_protect)) {
+    // TODO(crbug.com/1123153): Remove logging after the bug is fixed.
+    LOG(WARNING) << "Missing "
+                 << chromeos::system::kFirmwareWriteProtectCurrentKey
+                 << " statistics";
     return false;
   }
+  // TODO(crbug.com/1123153): Remove logging after the bug is fixed.
+  LOG(WARNING) << "Statistics "
+               << chromeos::system::kFirmwareWriteProtectCurrentKey << ": "
+               << firmware_write_protect;
 
   if (firmware_write_protect ==
       chromeos::system::kFirmwareWriteProtectCurrentValueOff) {

chrome/browser/chromeos/policy/status_uploader.cc

@@ -212,8 +212,14 @@ void StatusUploader::OnStatusReceived(StatusCollectorParams callback_params) {
     return;
   }
 
-  SYSLOG(INFO) << "Starting status upload: has_device_status = "
-               << has_device_status;
+  // TODO(crbug.com/1123153): Remove write_protect_switch logging after bugfix.
+  SYSLOG(INFO)
+      << "Starting status upload: has_device_status = " << has_device_status
+      << " write_protect_switch = "
+      << (callback_params.device_status &&
+                  callback_params.device_status->has_write_protect_switch()
+              ? callback_params.device_status->write_protect_switch()
+              : -1);
 
   client_->UploadDeviceStatus(callback_params.device_status.get(),
                               callback_params.session_status.get(),

chromeos/system/name_value_pairs_parser.cc

@@ -11,9 +11,11 @@
 #include "base/files/file_util.h"
 #include "base/logging.h"
 #include "base/process/launch.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/strings/string_tokenizer.h"
 #include "base/strings/string_util.h"
 #include "base/system/sys_info.h"
+#include "chromeos/system/statistics_provider.h"
 
 namespace chromeos {  // NOLINT
 namespace system {
@@ -51,10 +53,13 @@ bool NameValuePairsParser::GetNameValuePairsFromFile(
     const std::string& delim) {
   std::string contents;
   if (base::ReadFileToString(file_path, &contents)) {
-    return ParseNameValuePairs(contents, eq, delim);
+    return ParseNameValuePairs(contents, eq, delim,
+                               /*debug_source=*/file_path.value());
   } else {
-    if (base::SysInfo::IsRunningOnChromeOS())
-      VLOG(1) << "Statistics file not present: " << file_path.value();
+    if (base::SysInfo::IsRunningOnChromeOS()) {
+      // TODO(crbug.com/1123153): Downgrade to VLOG(1) after fixing the bug.
+      LOG(WARNING) << "Statistics file not present: " << file_path.value();
+    }
     return false;
   }
 }
@@ -65,12 +70,14 @@ bool NameValuePairsParser::ParseNameValuePairsFromTool(
     const std::string& eq,
     const std::string& delim,
     const std::string& comment_delim) {
+  DCHECK_GE(argc, 1);
+
   std::string output_string;
   if (!GetToolOutput(argc, argv, &output_string))
     return false;
 
-  return ParseNameValuePairsWithComments(output_string, eq, delim,
-                                         comment_delim);
+  return ParseNameValuePairsWithComments(
+      output_string, eq, delim, comment_delim, /*debug_source=*/argv[0]);
 }
 
 void NameValuePairsParser::DeletePairsWithValue(const std::string& value) {
@@ -96,17 +103,21 @@ void NameValuePairsParser::AddNameValuePair(const std::string& key,
   }
 }
 
-bool NameValuePairsParser::ParseNameValuePairs(const std::string& in_string,
-                                               const std::string& eq,
-                                               const std::string& delim) {
-  return ParseNameValuePairsWithComments(in_string, eq, delim, "");
+bool NameValuePairsParser::ParseNameValuePairs(
+    const std::string& in_string,
+    const std::string& eq,
+    const std::string& delim,
+    const std::string& debug_source) {
+  return ParseNameValuePairsWithComments(in_string, eq, delim, "",
+                                         debug_source);
 }
 
 bool NameValuePairsParser::ParseNameValuePairsWithComments(
     const std::string& in_string,
     const std::string& eq,
     const std::string& delim,
-    const std::string& comment_delim) {
+    const std::string& comment_delim,
+    const std::string& debug_source) {
   bool all_valid = true;
   // Set up the pair tokenizer.
   base::StringTokenizer pair_toks(in_string, delim);
@@ -114,6 +125,13 @@ bool NameValuePairsParser::ParseNameValuePairsWithComments(
   // Process token pairs.
   while (pair_toks.GetNext()) {
     std::string pair(pair_toks.token());
+
+    // TODO(crbug.com/1123153): Delete logging after the bug is fixed.
+    LOG_IF(WARNING,
+           pair.find(kFirmwareWriteProtectCurrentKey) != std::string::npos)
+        << "Statistics " << kFirmwareWriteProtectCurrentKey << " mentioned in "
+        << debug_source << ": " << base::HexEncode(pair.c_str(), pair.size());
+
     // Anything before the first |eq| is the key, anything after is the value.
     // |eq| must exist.
     size_t eq_pos = pair.find(eq);

chromeos/system/name_value_pairs_parser.h

@@ -60,7 +60,8 @@ class COMPONENT_EXPORT(CHROMEOS_SYSTEM) NameValuePairsParser {
   // be added to the map.
   bool ParseNameValuePairs(const std::string& in_string,
                            const std::string& eq,
-                           const std::string& delim);
+                           const std::string& delim,
+                           const std::string& debug_source);
 
   // This version allows for values which end with a comment beginning with
   // |comment_delim|.
@@ -70,7 +71,8 @@ class COMPONENT_EXPORT(CHROMEOS_SYSTEM) NameValuePairsParser {
   bool ParseNameValuePairsWithComments(const std::string& in_string,
                                        const std::string& eq,
                                        const std::string& delim,
-                                       const std::string& comment_delim);
+                                       const std::string& comment_delim,
+                                       const std::string& debug_source);
 
   NameValueMap* map_;
 

chromeos/system/name_value_pairs_parser_unittest.cc

@@ -14,7 +14,7 @@ TEST(NameValuePairsParser, TestParseNameValuePairs) {
   NameValuePairsParser::NameValueMap map;
   NameValuePairsParser parser(&map);
   const std::string contents1 = "foo=Foo bar=Bar\nfoobar=FooBar\n";
-  EXPECT_TRUE(parser.ParseNameValuePairs(contents1, "=", " \n"));
+  EXPECT_TRUE(parser.ParseNameValuePairs(contents1, "=", " \n", ""));
   EXPECT_EQ(3U, map.size());
   EXPECT_EQ("Foo", map["foo"]);
   EXPECT_EQ("Bar", map["bar"]);
@@ -22,21 +22,21 @@ TEST(NameValuePairsParser, TestParseNameValuePairs) {
 
   map.clear();
   const std::string contents2 = "foo=Foo,bar=Bar";
-  EXPECT_TRUE(parser.ParseNameValuePairs(contents2, "=", ",\n"));
+  EXPECT_TRUE(parser.ParseNameValuePairs(contents2, "=", ",\n", ""));
   EXPECT_EQ(2U, map.size());
   EXPECT_EQ("Foo", map["foo"]);
   EXPECT_EQ("Bar", map["bar"]);
 
   map.clear();
   const std::string contents3 = "foo=Foo=foo,bar=Bar";
-  EXPECT_TRUE(parser.ParseNameValuePairs(contents3, "=", ",\n"));
+  EXPECT_TRUE(parser.ParseNameValuePairs(contents3, "=", ",\n", ""));
   EXPECT_EQ(2U, map.size());
   EXPECT_EQ("Foo=foo", map["foo"]);
   EXPECT_EQ("Bar", map["bar"]);
 
   map.clear();
   const std::string contents4 = "foo=Foo,=Bar";
-  EXPECT_FALSE(parser.ParseNameValuePairs(contents4, "=", ",\n"));
+  EXPECT_FALSE(parser.ParseNameValuePairs(contents4, "=", ",\n", ""));
   EXPECT_EQ(1U, map.size());
   EXPECT_EQ("Foo", map["foo"]);
 
@@ -45,7 +45,7 @@ TEST(NameValuePairsParser, TestParseNameValuePairs) {
       "\"initial_locale\"=\"ja\"\n"
       "\"initial_timezone\"=\"Asia/Tokyo\"\n"
       "\"keyboard_layout\"=\"mozc-jp\"\n";
-  EXPECT_TRUE(parser.ParseNameValuePairs(contents5, "=", "\n"));
+  EXPECT_TRUE(parser.ParseNameValuePairs(contents5, "=", "\n", ""));
   EXPECT_EQ(3U, map.size());
   EXPECT_EQ("ja", map["initial_locale"]);
   EXPECT_EQ("Asia/Tokyo", map["initial_timezone"]);
@@ -57,8 +57,8 @@ TEST(NameValuePairsParser, TestParseNameValuePairsWithComments) {
   NameValuePairsParser parser(&map);
 
   const std::string contents1 = "foo=Foo,bar=#Bar,baz= 0 #Baz";
-  EXPECT_TRUE(parser.ParseNameValuePairsWithComments(
-      contents1, "=", ",\n", "#"));
+  EXPECT_TRUE(
+      parser.ParseNameValuePairsWithComments(contents1, "=", ",\n", "#", ""));
   EXPECT_EQ(3U, map.size());
   EXPECT_EQ("Foo", map["foo"]);
   EXPECT_EQ("", map["bar"]);
@@ -66,15 +66,15 @@ TEST(NameValuePairsParser, TestParseNameValuePairsWithComments) {
 
   map.clear();
   const std::string contents2 = "foo=";
-  EXPECT_TRUE(parser.ParseNameValuePairsWithComments(
-      contents2, "=", ",\n", "#"));
+  EXPECT_TRUE(
+      parser.ParseNameValuePairsWithComments(contents2, "=", ",\n", "#", ""));
   EXPECT_EQ(1U, map.size());
   EXPECT_EQ("", map["foo"]);
 
   map.clear();
   const std::string contents3 = " \t ,,#all empty,";
-  EXPECT_FALSE(parser.ParseNameValuePairsWithComments(
-      contents3, "=", ",\n", "#"));
+  EXPECT_FALSE(
+      parser.ParseNameValuePairsWithComments(contents3, "=", ",\n", "#", ""));
   EXPECT_EQ(0U, map.size());
 }
 

chromeos/system/statistics_provider.cc

@@ -317,7 +317,8 @@ void StatisticsProviderImpl::SignalStatisticsLoaded() {
     // and unblock pending WaitForStatisticsLoaded() calls.
     statistics_loaded_.Signal();
 
-    VLOG(1) << "Finished loading statistics.";
+    // TODO(crbug.com/1123153): Downgrade to VLOG(1) after the bug is fixed.
+    LOG(WARNING) << "Finished loading statistics.";
   }
 
   // Schedule callbacks that were in |statistics_loaded_callbacks_|.
@@ -616,7 +617,8 @@ void StatisticsProviderImpl::LoadMachineStatistics(bool load_oem_manifest) {
     region_ =
         command_line->GetSwitchValueASCII(chromeos::switches::kCrosRegion);
     machine_info_[kRegionKey] = region_;
-    VLOG(1) << "CrOS region set to '" << region_ << "'";
+    // TODO(crbug.com/1123153): Downgrade to VLOG(1) after the bug is fixed.
+    LOG(WARNING) << "CrOS region set to '" << region_ << "'";
   }
 
   if (regional_data_.get() && !region_.empty() && !GetRegionDictionary())
@@ -664,7 +666,8 @@ void StatisticsProviderImpl::LoadOemManifestFromFile(
   machine_flags_[kOemKeyboardDrivenOobeKey] = oem_manifest.keyboard_driven_oobe;
 
   oem_manifest_loaded_ = true;
-  VLOG(1) << "Loaded OEM Manifest statistics from " << file.value();
+  // TODO(crbug.com/1123153): Downgrade to VLOG(1) after the bug is fixed.
+  LOG(WARNING) << "Loaded OEM Manifest statistics from " << file.value();
 }
 
 StatisticsProviderImpl* StatisticsProviderImpl::GetInstance() {