Skip to content

GitLab

T
tangled
Commit 5146474c authored by Josh Nohle's avatar Josh Nohle Committed by Commit Bot
Browse files
Options

[DeviceSync v2] Add metrics to CryptAuth metadata syncer 

Bug: 951969, 936273
Change-Id: I4bede74331ade6af2776fe665b4e682f031d45aa
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1987070
Commit-Queue: Josh Nohle <nohle@chromium.org>
Reviewed-by: default avatarSteven Holte <holte@chromium.org>
Cr-Commit-Position: refs/heads/master@{#735951}
parent 3b677934
Hide whitespace changes
Inline Side-by-side
Showing with 130 additions and 24 deletions
chromeos/services/device_sync/cryptauth_metadata_syncer_impl.cc
View file @ 5146474c
......@@ -8,6 +8,7 @@
#include "base/bind.h"
#include "base/memory/ptr_util.h"
#include "base/metrics/histogram_functions.h"
#include "base/no_destructor.h"
#include "base/stl_util.h"
#include "chromeos/components/multidevice/logging/logging.h"
......@@ -15,6 +16,7 @@
#include "chromeos/services/device_sync/cryptauth_client.h"
#include "chromeos/services/device_sync/cryptauth_ecies_encryptor_impl.h"
#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/value_string_encoding.h"
namespace chromeos {
......@@ -65,30 +67,47 @@ SyncMetadataNetworkRequestErrorToResultCode(NetworkRequestError error) {
}
}
void RecordGroupKeyCreationMetrics(const base::TimeDelta& execution_time) {
void RecordGroupKeyCreationMetrics(const base::TimeDelta& execution_time,
CryptAuthAsyncTaskResult result) {
LogAsyncExecutionTimeMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.ExecutionTime.GroupKeyCreation",
execution_time);
LogCryptAuthAsyncTaskSuccessMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.AsyncTaskResult.GroupKeyCreation",
result);
}
void RecordLocalDeviceMetadataEncryptionMetrics(
const base::TimeDelta& execution_time) {
const base::TimeDelta& execution_time,
CryptAuthAsyncTaskResult result) {
LogAsyncExecutionTimeMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.ExecutionTime."
"LocalDeviceMetadataEncryption",
execution_time);
LogCryptAuthAsyncTaskSuccessMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.AsyncTaskResult."
"LocalDeviceMetadataEncryption",
result);
}
void RecordFirstSyncMetadataMetrics(const base::TimeDelta& execution_time) {
void RecordFirstSyncMetadataMetrics(const base::TimeDelta& execution_time,
CryptAuthApiCallResult result) {
LogAsyncExecutionTimeMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.ExecutionTime.FirstSyncMetadata",
execution_time);
LogCryptAuthApiCallSuccessMetric(
"CryptAuth.DeviceSyncV2.MetdataSyncer.ApiCallResult.FirstSyncMetadata",
result);
}
void RecordSecondSyncMetadataMetrics(const base::TimeDelta& execution_time) {
void RecordSecondSyncMetadataMetrics(const base::TimeDelta& execution_time,
CryptAuthApiCallResult result) {
LogAsyncExecutionTimeMetric(
"CryptAuth.DeviceSyncV2.MetadataSyncer.ExecutionTime.SecondSyncMetadata",
execution_time);
LogCryptAuthApiCallSuccessMetric(
"CryptAuth.DeviceSyncV2.MetdataSyncer.ApiCallResult.SecondSyncMetadata",
result);
}
} // namespace
......@@ -196,8 +215,6 @@ void CryptAuthMetadataSyncerImpl::SetState(State state) {
if (!timeout_for_state)
return;
// TODO(https://crbug.com/936273): Add metrics to track failure rates due to
// async timeouts.
timer_->Start(FROM_HERE, *timeout_for_state,
base::BindOnce(&CryptAuthMetadataSyncerImpl::OnTimeout,
base::Unretained(this)));
......@@ -213,16 +230,20 @@ void CryptAuthMetadataSyncerImpl::OnTimeout() {
base::TimeTicks::Now() - last_state_change_timestamp_;
switch (state_) {
case State::kWaitingForGroupKeyCreation:
RecordGroupKeyCreationMetrics(execution_time);
RecordGroupKeyCreationMetrics(execution_time,
CryptAuthAsyncTaskResult::kTimeout);
break;
case State::kWaitingForLocalDeviceMetadataEncryption:
RecordLocalDeviceMetadataEncryptionMetrics(execution_time);
RecordLocalDeviceMetadataEncryptionMetrics(
execution_time, CryptAuthAsyncTaskResult::kTimeout);
break;
case State::kWaitingForFirstSyncMetadataResponse:
RecordFirstSyncMetadataMetrics(execution_time);
RecordFirstSyncMetadataMetrics(execution_time,
CryptAuthApiCallResult::kTimeout);
break;
case State::kWaitingForSecondSyncMetadataResponse:
RecordSecondSyncMetadataMetrics(execution_time);
RecordSecondSyncMetadataMetrics(execution_time,
CryptAuthApiCallResult::kTimeout);
break;
default:
NOTREACHED();
......@@ -334,10 +355,13 @@ void CryptAuthMetadataSyncerImpl::OnLocalDeviceMetadataEncrypted(
const base::Optional<std::string>& encrypted_metadata) {
DCHECK_EQ(State::kWaitingForLocalDeviceMetadataEncryption, state_);
RecordLocalDeviceMetadataEncryptionMetrics(base::TimeTicks::Now() -
last_state_change_timestamp_);
bool success = encrypted_metadata.has_value();
RecordLocalDeviceMetadataEncryptionMetrics(
base::TimeTicks::Now() - last_state_change_timestamp_,
success ? CryptAuthAsyncTaskResult::kSuccess
: CryptAuthAsyncTaskResult::kError);
if (!encrypted_metadata) {
if (!success) {
FinishAttempt(
CryptAuthDeviceSyncResult::ResultCode::kErrorEncryptingDeviceMetadata);
return;
......@@ -367,14 +391,17 @@ void CryptAuthMetadataSyncerImpl::OnGroupKeyCreated(
const base::Optional<CryptAuthKey>& client_ephemeral_dh) {
DCHECK_EQ(State::kWaitingForGroupKeyCreation, state_);
RecordGroupKeyCreationMetrics(base::TimeTicks::Now() -
last_state_change_timestamp_);
const auto it = new_keys.find(
CryptAuthKeyBundle::Name::kDeviceSyncBetterTogetherGroupKey);
DCHECK(it != new_keys.end());
if (!it->second) {
bool success = it->second.has_value();
RecordGroupKeyCreationMetrics(
base::TimeTicks::Now() - last_state_change_timestamp_,
success ? CryptAuthAsyncTaskResult::kSuccess
: CryptAuthAsyncTaskResult::kError);
if (!success) {
FinishAttempt(
CryptAuthDeviceSyncResult::ResultCode::kErrorCreatingGroupKey);
return;
......@@ -425,9 +452,11 @@ void CryptAuthMetadataSyncerImpl::OnSyncMetadataSuccess(
base::TimeDelta execution_time =
base::TimeTicks::Now() - last_state_change_timestamp_;
if (state_ == State::kWaitingForFirstSyncMetadataResponse)
RecordFirstSyncMetadataMetrics(execution_time);
RecordFirstSyncMetadataMetrics(execution_time,
CryptAuthApiCallResult::kSuccess);
else if (state_ == State::kWaitingForSecondSyncMetadataResponse)
RecordSecondSyncMetadataMetrics(execution_time);
RecordSecondSyncMetadataMetrics(execution_time,
CryptAuthApiCallResult::kSuccess);
else
NOTREACHED();
......@@ -441,9 +470,11 @@ void CryptAuthMetadataSyncerImpl::OnSyncMetadataFailure(
base::TimeDelta execution_time =
base::TimeTicks::Now() - last_state_change_timestamp_;
if (state_ == State::kWaitingForFirstSyncMetadataResponse)
RecordFirstSyncMetadataMetrics(execution_time);
RecordFirstSyncMetadataMetrics(
execution_time, CryptAuthApiCallResultFromNetworkRequestError(error));
else if (state_ == State::kWaitingForSecondSyncMetadataResponse)
RecordSecondSyncMetadataMetrics(execution_time);
RecordSecondSyncMetadataMetrics(
execution_time, CryptAuthApiCallResultFromNetworkRequestError(error));
else
NOTREACHED();
......@@ -465,11 +496,12 @@ void CryptAuthMetadataSyncerImpl::FilterMetadataAndFinishAttempt() {
bool did_non_fatal_error_occur = false;
for (const cryptauthv2::DeviceMetadataPacket& metadata :
sync_metadata_response_->encrypted_metadata()) {
// TODO(https://crbug.com/936273): Log metrics for invalid
// DeviceMetadataPackets.
bool is_device_metadata_packet_valid =
!metadata.device_id().empty() && !metadata.device_name().empty() &&
!metadata.device_public_key().empty();
base::UmaHistogramBoolean(
"CryptAuth.DeviceSyncV2.MetadataSyncer.IsDeviceMetadataPacketValid",
is_device_metadata_packet_valid);
if (!is_device_metadata_packet_valid) {
PA_LOG(ERROR) << "Invalid DeviceMetadataPacket: device_id = "
<< metadata.device_id() << ", device_public_key = "
......@@ -480,9 +512,11 @@ void CryptAuthMetadataSyncerImpl::FilterMetadataAndFinishAttempt() {
continue;
}
// TODO(https://crbug.com/936273): Log metrics for duplicate device IDs.
bool is_duplicate_id =
base::Contains(id_to_device_metadata_packet_map_, metadata.device_id());
base::UmaHistogramBoolean(
"CryptAuth.DeviceSyncV2.MetadataSyncer.IsDuplicateDeviceId",
is_duplicate_id);
if (is_duplicate_id) {
PA_LOG(ERROR) << "Duplicate device IDs (" << metadata.device_id()
<< ") in SyncMetadata response.";
......
tools/metrics/histograms/histograms.xml
View file @ 5146474c
......@@ -29771,6 +29771,54 @@ uploading your change for review.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.ApiCallResult.FirstSyncMetadata"
enum="CryptAuthApiCallResult" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records the result of the first async SyncMetadata API call during the
CryptAuth v2 DeviceSync flow. Recorded when the async callback is invoked or
when the call times out.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.ApiCallResult.SecondSyncMetadata"
enum="CryptAuthApiCallResult" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records the result of the second async SyncMetadata API call during the
CryptAuth v2 DeviceSync flow. Recorded when the async callback is invoked or
when the call times out.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.AsyncTaskResult.GroupKeyCreation"
enum="CryptAuthAsyncTaskResult" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records the result of the async group key creation during the CryptAuth v2
DeviceSync flow. Recorded when the async callback is invoked or when the
call times out.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.AsyncTaskResult.LocalDeviceMetadataEncryption"
enum="CryptAuthAsyncTaskResult" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records the result of the async local device metadata encryption during the
CryptAuth v2 DeviceSync flow. Recorded when the async callback is invoked or
when the call times out.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.ExecutionTime.FirstSyncMetadata"
units="ms" expires_after="2020-12-15">
......@@ -29819,6 +29867,30 @@ uploading your change for review.
</summary>
</histogram>
<histogram
name="CryptAuth.DeviceSyncV2.MetadataSyncer.IsDeviceMetadataPacketValid"
enum="Boolean" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records whether or not the device metadata packets sent by CryptAuth have
all of the necessary fields populated. Emitted for each device metadata
packet during the SyncMetadata phase of the CryptAuth v2 DeviceSync flow.
</summary>
</histogram>
<histogram name="CryptAuth.DeviceSyncV2.MetadataSyncer.IsDuplicateDeviceId"
enum="Boolean" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
<owner>better-together-dev@google.com</owner>
<summary>
Records whether or not the device ID from a device metadata packet sent by
CryptAuth in the SyncMetadata response has the same ID as a packet from the
same response. Emitted for each device metadata packet during the
SyncMetadata phase of the CryptAuth v2 DeviceSync flow.
</summary>
</histogram>
<histogram name="CryptAuth.DeviceSyncV2.Result.DidDeviceRegistryChange"
enum="BooleanChanged" expires_after="2020-12-15">
<owner>nohle@chromium.org</owner>
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment