[DeviceSync v2] Add logging tools for protos

Add functions to print CryptAuth protos in JSON format. Use these for
verbose logs throughout the v2 DeviceSync flow.

Note: cryptauth_logging.h is included in the enrollment and device
managers to allow for better printing of the InvocationReason.

Manually tested to verify formatting.

Bug: 951969
Change-Id: Icb9540541f6a080f7bd6f1e661c124eb610dcc91
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2091707Reviewed-by: James Vecore <vecore@google.com>
Commit-Queue: Josh Nohle <nohle@chromium.org>
Cr-Commit-Position: refs/heads/master@{#748342}

chromeos/services/device_sync/cryptauth_device_activity_getter_impl.cc

@@ -21,6 +21,7 @@
 #include "chromeos/services/device_sync/cryptauth_key_bundle.h"
 #include "chromeos/services/device_sync/cryptauth_task_metrics_logger.h"
 #include "chromeos/services/device_sync/device_sync_type_converters.h"
+#include "chromeos/services/device_sync/proto/cryptauth_logging.h"
 
 namespace chromeos {
 
@@ -200,6 +201,8 @@ void CryptAuthDeviceActivityGetterImpl::OnGetDevicesActivityStatusSuccess(
       base::TimeTicks::Now() - last_state_change_timestamp_,
       CryptAuthApiCallResult::kSuccess);
 
+  PA_LOG(VERBOSE) << "GetDevicesActivityStatus response:\n" << response;
+
   DeviceActivityStatusResult device_activity_statuses;
 
   for (const cryptauthv2::DeviceActivityStatus& device_activity_status :

chromeos/services/device_sync/cryptauth_metadata_syncer_impl.cc

@@ -17,6 +17,7 @@
 #include "chromeos/services/device_sync/cryptauth_key_creator_impl.h"
 #include "chromeos/services/device_sync/cryptauth_task_metrics_logger.h"
 #include "chromeos/services/device_sync/pref_names.h"
+#include "chromeos/services/device_sync/proto/cryptauth_logging.h"
 #include "chromeos/services/device_sync/value_string_encoding.h"
 #include "components/prefs/pref_registry_simple.h"
 #include "components/prefs/pref_service.h"
@@ -296,8 +297,11 @@ CryptAuthMetadataSyncerImpl::GetGroupPublicKeyState() {
 
 void CryptAuthMetadataSyncerImpl::AttemptNextStep() {
   switch (state_) {
-    case State::kNotStarted:
-      switch (GetGroupPublicKeyState()) {
+    // Start the flow.
+    case State::kNotStarted: {
+      GroupPublicKeyState group_public_key_state = GetGroupPublicKeyState();
+      PA_LOG(VERBOSE) << "Group public key state: " << group_public_key_state;
+      switch (group_public_key_state) {
         case GroupPublicKeyState::kNewKeyNeedsToBeCreated:
           CreateGroupKey();
           return;
@@ -308,17 +312,25 @@ void CryptAuthMetadataSyncerImpl::AttemptNextStep() {
           NOTREACHED();
           return;
       }
+    }
 
+    // After group key creation, encrypt the local device metadata.
     case State::kWaitingForGroupKeyCreation:
       EncryptLocalDeviceMetadata();
       return;
 
+    // After local device metadata is encrypted, start constructing the
+    // SyncMetadata call.
     case State::kWaitingForLocalDeviceMetadataEncryption:
       MakeSyncMetadataCall();
       return;
 
-    case State::kWaitingForFirstSyncMetadataResponse:
-      switch (GetGroupPublicKeyState()) {
+    // After receiving the first SyncMetadata response, take further action
+    // based on the state of the group public key.
+    case State::kWaitingForFirstSyncMetadataResponse: {
+      GroupPublicKeyState group_public_key_state = GetGroupPublicKeyState();
+      PA_LOG(VERBOSE) << "Group public key state: " << group_public_key_state;
+      switch (group_public_key_state) {
         case GroupPublicKeyState::kNewKeyNeedsToBeCreated:
           CreateGroupKey();
           return;
@@ -336,11 +348,16 @@ void CryptAuthMetadataSyncerImpl::AttemptNextStep() {
           NOTREACHED();
           return;
       }
+    }
 
-    case State::kWaitingForSecondSyncMetadataResponse:
-      // No more than two SyncMetadata requests should be necessary in the v2
-      // DeviceSync protocol to establish the group public key.
-      switch (GetGroupPublicKeyState()) {
+    // After receiving the second SyncMetadata response, process the metadata
+    // and finish. Note: In the v2 DeviceSync protocol, no more than two
+    // SyncMetadata requests should be necessary to establish the group public
+    // key.
+    case State::kWaitingForSecondSyncMetadataResponse: {
+      GroupPublicKeyState group_public_key_state = GetGroupPublicKeyState();
+      PA_LOG(VERBOSE) << "Group public key state: " << group_public_key_state;
+      switch (group_public_key_state) {
         case GroupPublicKeyState::kEstablished:
           FilterMetadataAndFinishAttempt();
           return;
@@ -349,7 +366,9 @@ void CryptAuthMetadataSyncerImpl::AttemptNextStep() {
                             kErrorEstablishingGroupPublicKey);
           return;
       }
+    }
 
+    // Each CryptAuthMetadataSyncer object can only be used once.
     case State::kFinished:
       NOTREACHED();
       return;
@@ -505,6 +524,8 @@ void CryptAuthMetadataSyncerImpl::OnSyncMetadataSuccess(
   else
     NOTREACHED();
 
+  PA_LOG(VERBOSE) << "SyncMetadata response:\n" << response;
+
   // Cache encrypted and unencrypted local device metadata, along with the group
   // public key used to encrypt the data, that was successfully sent in the
   // SyncMetadata request. Note: the cached group public key might not match
@@ -668,6 +689,33 @@ std::ostream& operator<<(std::ostream& stream,
   return stream;
 }
 
+std::ostream& operator<<(
+    std::ostream& stream,
+    const CryptAuthMetadataSyncerImpl::GroupPublicKeyState& key_state) {
+  switch (key_state) {
+    case CryptAuthMetadataSyncerImpl::GroupPublicKeyState::kUndetermined:
+      stream << "[Undetermined]";
+      break;
+    case CryptAuthMetadataSyncerImpl::GroupPublicKeyState::
+        kKeyExistsButNotConfirmedWithCryptAuth:
+      stream << "[Key exists but not confirmed with CryptAuth]";
+      break;
+    case CryptAuthMetadataSyncerImpl::GroupPublicKeyState::
+        kNewKeyNeedsToBeCreated:
+      stream << "[New key needs to be created]";
+      break;
+    case CryptAuthMetadataSyncerImpl::GroupPublicKeyState::
+        kNewKeyReceivedFromCryptAuth:
+      stream << "[New key received from CryptAuth]";
+      break;
+    case CryptAuthMetadataSyncerImpl::GroupPublicKeyState::kEstablished:
+      stream << "[Established]";
+      break;
+  }
+
+  return stream;
+}
+
 }  // namespace device_sync
 
 }  // namespace chromeos

chromeos/services/device_sync/cryptauth_metadata_syncer_impl.h

@@ -77,6 +77,7 @@ class CryptAuthMetadataSyncerImpl : public CryptAuthMetadataSyncer {
     kWaitingForSecondSyncMetadataResponse,
     kFinished
   };
+  friend std::ostream& operator<<(std::ostream& stream, const State& state);
 
   // kKeyExistsButNotConfirmedWithCryptAuth: A local group public key exists but
   //     CryptAuth has yet to confirm or deny that it is the correct group key.
@@ -98,8 +99,8 @@ class CryptAuthMetadataSyncerImpl : public CryptAuthMetadataSyncer {
     kNewKeyReceivedFromCryptAuth,
     kEstablished
   };
-
-  friend std::ostream& operator<<(std::ostream& stream, const State& state);
+  friend std::ostream& operator<<(std::ostream& stream,
+                                  const GroupPublicKeyState& state);
 
   static base::Optional<base::TimeDelta> GetTimeoutForState(State state);
   static base::Optional<CryptAuthDeviceSyncResult::ResultCode>

chromeos/services/device_sync/cryptauth_scheduler_impl.cc

@@ -13,6 +13,7 @@
 #include "chromeos/network/network_state.h"
 #include "chromeos/network/network_state_handler.h"
 #include "chromeos/services/device_sync/pref_names.h"
+#include "chromeos/services/device_sync/proto/cryptauth_logging.h"
 #include "chromeos/services/device_sync/value_string_encoding.h"
 #include "components/prefs/pref_registry_simple.h"
 #include "components/prefs/pref_service.h"
@@ -331,7 +332,7 @@ void CryptAuthSchedulerImpl::HandleResult(
 
   if (new_client_directive && IsClientDirectiveValid(*new_client_directive)) {
     client_directive_ = *new_client_directive;
-
+    PA_LOG(VERBOSE) << "New client directive:\n" << client_directive_;
     pref_service_->Set(
         prefs::kCryptAuthSchedulerClientDirective,
         util::EncodeProtoMessageAsValueString(&client_directive_));

chromeos/services/device_sync/cryptauth_v2_device_manager_impl.cc

@@ -14,6 +14,7 @@
 #include "chromeos/services/device_sync/cryptauth_device_syncer_impl.h"
 #include "chromeos/services/device_sync/cryptauth_key_registry.h"
 #include "chromeos/services/device_sync/cryptauth_task_metrics_logger.h"
+#include "chromeos/services/device_sync/proto/cryptauth_logging.h"
 #include "chromeos/services/device_sync/public/cpp/client_app_metadata_provider.h"
 
 namespace chromeos {

chromeos/services/device_sync/cryptauth_v2_enrollment_manager_impl.cc

@@ -18,6 +18,7 @@
 #include "chromeos/services/device_sync/cryptauth_task_metrics_logger.h"
 #include "chromeos/services/device_sync/cryptauth_v2_enroller_impl.h"
 #include "chromeos/services/device_sync/pref_names.h"
+#include "chromeos/services/device_sync/proto/cryptauth_logging.h"
 #include "chromeos/services/device_sync/public/cpp/client_app_metadata_provider.h"
 #include "chromeos/services/device_sync/value_string_encoding.h"
 #include "components/prefs/pref_registry_simple.h"

chromeos/services/device_sync/proto/BUILD.gn

@@ -20,6 +20,8 @@ proto_library("proto") {
 
 static_library("util") {
   sources = [
+    "cryptauth_logging.cc",
+    "cryptauth_logging.h",
     "cryptauth_proto_to_query_parameters_util.cc",
     "cryptauth_proto_to_query_parameters_util.h",
     "device_classifier_util.cc",
@@ -32,6 +34,7 @@ static_library("util") {
 
   deps = [
     "//base",
+    "//base:i18n",
     "//components/version_info",
   ]
 }

chromeos/services/device_sync/proto/cryptauth_logging.h

+// Copyright 2020 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.
+
+#ifndef CHROMEOS_SERVICES_DEVICE_SYNC_PROTO_CRYPTAUTH_LOGGING_H_
+#define CHROMEOS_SERVICES_DEVICE_SYNC_PROTO_CRYPTAUTH_LOGGING_H_
+
+#include <ostream>
+#include <string>
+
+#include "base/values.h"
+#include "chromeos/services/device_sync/proto/cryptauth_better_together_device_metadata.pb.h"
+#include "chromeos/services/device_sync/proto/cryptauth_common.pb.h"
+#include "chromeos/services/device_sync/proto/cryptauth_devicesync.pb.h"
+#include "chromeos/services/device_sync/proto/cryptauth_directive.pb.h"
+
+namespace cryptauthv2 {
+
+std::string TruncateStringForLogs(const std::string& str);
+
+std::string TargetServiceToString(TargetService service);
+std::ostream& operator<<(std::ostream& stream, const TargetService& service);
+
+std::string InvocationReasonToString(ClientMetadata::InvocationReason reason);
+std::ostream& operator<<(std::ostream& stream,
+                         const ClientMetadata::InvocationReason& reason);
+
+std::string ConnectivityStatusToString(ConnectivityStatus status);
+std::ostream& operator<<(std::ostream& stream,
+                         const ConnectivityStatus& status);
+
+base::Value PolicyReferenceToReadableDictionary(const PolicyReference& policy);
+std::ostream& operator<<(std::ostream& stream, const PolicyReference& policy);
+
+base::Value InvokeNextToReadableDictionary(const InvokeNext& invoke_next);
+std::ostream& operator<<(std::ostream& stream, const InvokeNext& invoke_next);
+
+base::Value ClientDirectiveToReadableDictionary(
+    const ClientDirective& directive);
+std::ostream& operator<<(std::ostream& stream,
+                         const ClientDirective& directive);
+
+base::Value DeviceMetadataPacketToReadableDictionary(
+    const DeviceMetadataPacket& packet);
+std::ostream& operator<<(std::ostream& stream,
+                         const DeviceMetadataPacket& packet);
+
+base::Value EncryptedGroupPrivateKeyToReadableDictionary(
+    const EncryptedGroupPrivateKey& key);
+std::ostream& operator<<(std::ostream& stream,
+                         const EncryptedGroupPrivateKey& key);
+
+base::Value SyncMetadataResponseToReadableDictionary(
+    const SyncMetadataResponse& response);
+std::ostream& operator<<(std::ostream& stream,
+                         const SyncMetadataResponse& response);
+
+base::Value FeatureStatusToReadableDictionary(
+    const DeviceFeatureStatus::FeatureStatus& status);
+std::ostream& operator<<(std::ostream& stream,
+                         const DeviceFeatureStatus::FeatureStatus& status);
+
+base::Value DeviceFeatureStatusToReadableDictionary(
+    const DeviceFeatureStatus& status);
+std::ostream& operator<<(std::ostream& stream,
+                         const DeviceFeatureStatus& status);
+
+base::Value BatchGetFeatureStatusesResponseToReadableDictionary(
+    const BatchGetFeatureStatusesResponse& response);
+std::ostream& operator<<(std::ostream& stream,
+                         const BatchGetFeatureStatusesResponse& response);
+
+base::Value DeviceActivityStatusToReadableDictionary(
+    const DeviceActivityStatus& status);
+std::ostream& operator<<(std::ostream& stream,
+                         const DeviceActivityStatus& status);
+
+base::Value GetDevicesActivityStatusResponseToReadableDictionary(
+    const GetDevicesActivityStatusResponse& response);
+std::ostream& operator<<(std::ostream& stream,
+                         const GetDevicesActivityStatusResponse& response);
+
+base::Value BeaconSeedToReadableDictionary(const BeaconSeed& seed);
+std::ostream& operator<<(std::ostream& stream, const BeaconSeed& seed);
+
+base::Value BetterTogetherDeviceMetadataToReadableDictionary(
+    const BetterTogetherDeviceMetadata& metadata);
+std::ostream& operator<<(std::ostream& stream,
+                         const BetterTogetherDeviceMetadata& metadata);
+
+}  // namespace cryptauthv2
+
+#endif  // CHROMEOS_SERVICES_DEVICE_SYNC_PROTO_CRYPTAUTH_LOGGING_H_