Log FakeServer sync traffic when tests fail

Many flaky sync tests cannot be reproduced locally and even flake
occasionally on bots. Hence, let's be verbose when they do fail, and
print a detailed trace of the sync traffic as experienced by the
FakeServer.

This is achieved by leveraging gTest's ScopedTrace.

Such detailed log should be, in many cases, sufficient to understand
what caused the flake.

Bug: 1017645,1014086
Change-Id: Icd9bf9637cfb6dd7da789aa0adee5c7161339b86
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1883651
Commit-Queue: Mikel Astiz <mastiz@chromium.org>
Reviewed-by: Marc Treib <treib@chromium.org>
Cr-Commit-Position: refs/heads/master@{#709907}

components/sync/test/fake_server/BUILD.gn

@@ -34,6 +34,7 @@ static_library("fake_server") {
   ]
 
   public_deps = [
+    "//testing/gmock",
     "//third_party/protobuf:protobuf_lite",
   ]
 

components/sync/test/fake_server/fake_server.cc

@@ -11,6 +11,7 @@
 
 #include "base/guid.h"
 #include "base/hash/hash.h"
+#include "base/json/json_writer.h"
 #include "base/logging.h"
 #include "base/stl_util.h"
 #include "base/strings/string_number_conversions.h"
@@ -20,7 +21,9 @@
 #include "base/synchronization/lock.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
+#include "base/values.h"
 #include "components/sync/engine_impl/net/server_connection_manager.h"
+#include "components/sync/protocol/proto_value_conversions.h"
 #include "net/base/net_errors.h"
 #include "net/http/http_status_code.h"
 
@@ -161,6 +164,13 @@ void PopulateWalletResults(
   }
 }
 
+std::string PrettyPrintValue(std::unique_ptr<base::DictionaryValue> value) {
+  std::string message;
+  base::JSONWriter::WriteWithOptions(
+      *value, base::JSONWriter::OPTIONS_PRETTY_PRINT, &message);
+  return message;
+}
+
 }  // namespace
 
 bool AreWalletDataProgressMarkersEquivalent(
@@ -185,6 +195,10 @@ net::HttpStatusCode FakeServer::HandleCommand(const std::string& request,
   bool parsed = message.ParseFromString(request);
   DCHECK(parsed) << "Unable to parse the ClientToServerMessage.";
 
+  LogForTestFailure(FROM_HERE, "REQUEST",
+                    PrettyPrintValue(syncer::ClientToServerMessageToValue(
+                        message, /*include_specifics=*/true)));
+
   sync_pb::ClientToServerResponse response_proto;
   if (message.message_contents() == sync_pb::ClientToServerMessage::COMMIT &&
       commit_error_type_ != sync_pb::SyncEnums::SUCCESS &&
@@ -229,9 +243,21 @@ net::HttpStatusCode FakeServer::HandleCommand(const std::string& request,
     if (http_status_code == net::HTTP_OK) {
       InjectClientCommand(response);
     }
+
+    // Parse the proto for logging purposes.
+    response_proto.ParseFromString(*response);
+    LogForTestFailure(FROM_HERE, "RESPONSE",
+                      PrettyPrintValue(syncer::ClientToServerResponseToValue(
+                          response_proto, /*include_specifics=*/true)));
+
     return http_status_code;
   }
 
+  LogForTestFailure(FROM_HERE, "RESPONSE",
+                    PrettyPrintValue(syncer::ClientToServerResponseToValue(
+                        response_proto,
+                        /*include_specifics=*/true)));
+
   response_proto.set_store_birthday(loopback_server_->GetStoreBirthday());
   *response = response_proto.SerializeAsString();
   return net::HTTP_OK;
@@ -488,4 +514,13 @@ base::WeakPtr<FakeServer> FakeServer::AsWeakPtr() {
   return weak_ptr_factory_.GetWeakPtr();
 }
 
+void FakeServer::LogForTestFailure(const base::Location& location,
+                                   const std::string& title,
+                                   const std::string& body) {
+  gtest_scoped_traces_.push_back(std::make_unique<testing::ScopedTrace>(
+      location.file_name(), location.line_number(),
+      base::StringPrintf("--- %s %d (reverse chronological order) ---\n%s",
+                         title.c_str(), request_counter_, body.c_str())));
+}
+
 }  // namespace fake_server

components/sync/test/fake_server/fake_server.h

@@ -14,6 +14,7 @@
 #include <vector>
 
 #include "base/files/scoped_temp_dir.h"
+#include "base/location.h"
 #include "base/observer_list.h"
 #include "base/optional.h"
 #include "base/threading/thread_checker.h"
@@ -27,6 +28,7 @@
 #include "components/sync/protocol/client_commands.pb.h"
 #include "components/sync/protocol/sync.pb.h"
 #include "net/http/http_status_code.h"
+#include "testing/gmock/include/gmock/gmock.h"
 
 namespace fake_server {
 
@@ -217,6 +219,14 @@ class FakeServer : public syncer::LoopbackServer::ObserverForTests {
       const sync_pb::DataTypeProgressMarker& old_wallet_marker,
       std::string* response_string);
 
+  // Logs a string that is meant to be shown in case the running test fails.
+  void LogForTestFailure(const base::Location& location,
+                         const std::string& title,
+                         const std::string& body);
+
+  // List used to implement LogForTestFailure().
+  std::vector<std::unique_ptr<testing::ScopedTrace>> gtest_scoped_traces_;
+
   // If set, the server will return HTTP errors.
   base::Optional<net::HttpStatusCode> http_error_status_code_;