PSM: Record Hash dance protocol duration correctly

Hash dance timer usually starts off whenever the
AutoEnrollmentCientImpl is going to start
i.e. AutoEnrollmentCientImpl::Start(). However,
as PSM is being executed in the beginning,
before Hash dance sequentially, that will make the
resulting Hash timer record Hash dance duration +
PSM duration.

This CL is starting the timer of Hash dance only when
preparing and sending off the Hash dance request. Also,
it adds its required regression tests.

BUG=chromium:1157317

Change-Id: Ie4aa0b8a3bd6cf296e3804995cacc45c23833c80
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2582121
Commit-Queue: Amr Aboelkher <amraboelkher@google.com>
Reviewed-by: Pavol Marko <pmarko@chromium.org>
Reviewed-by: Maksim Ivanov <emaxx@chromium.org>
Reviewed-by: Roland Bock <rbock@google.com>
Cr-Commit-Position: refs/heads/master@{#835850}

chrome/browser/chromeos/policy/auto_enrollment_client_impl.cc

@@ -882,8 +882,8 @@ void AutoEnrollmentClientImpl::Start() {
 
   // Drop the previous job and reset state.
   request_job_.reset();
+  hash_dance_time_start_ = base::TimeTicks();
   state_ = AUTO_ENROLLMENT_STATE_PENDING;
-  time_start_ = base::TimeTicks::Now();
   modulus_updates_received_ = 0;
   has_server_state_ = false;
   device_state_available_ = false;
@@ -896,7 +896,9 @@ void AutoEnrollmentClientImpl::Retry() {
 }
 
 void AutoEnrollmentClientImpl::CancelAndDeleteSoon() {
-  if (time_start_.is_null() || !request_job_) {
+  // Check if neither Hash dance request i.e. DeviceAutoEnrollmentRequest nor
+  // DeviceStateRetrievalRequest is in progress.
+  if (!request_job_) {
     // The client isn't running, just delete it.
     delete this;
   } else {
@@ -1092,6 +1094,10 @@ void AutoEnrollmentClientImpl::NextStep() {
 }
 
 void AutoEnrollmentClientImpl::SendBucketDownloadRequest() {
+  // Start the Hash dance timer during the first attempt.
+  if (hash_dance_time_start_.is_null())
+    hash_dance_time_start_ = base::TimeTicks::Now();
+
   std::string id_hash = device_identifier_provider_->GetIdHash();
   // Currently AutoEnrollmentClientImpl supports working with hashes that are at
   // least 8 bytes long. If this is reduced, the computation of the remainder
@@ -1328,8 +1334,8 @@ void AutoEnrollmentClientImpl::UpdateBucketDownloadTimingHistograms() {
   static const int kBuckets = 50;
 
   base::TimeTicks now = base::TimeTicks::Now();
-  if (!time_start_.is_null()) {
-    base::TimeDelta delta = now - time_start_;
+  if (!hash_dance_time_start_.is_null()) {
+    base::TimeDelta delta = now - hash_dance_time_start_;
     base::UmaHistogramCustomTimes(kUMAHashDanceProtocolTime + uma_suffix_,
                                   delta, kMin, kMax, kBuckets);
   }
@@ -1356,8 +1362,8 @@ void AutoEnrollmentClientImpl::RecordHashDanceSuccessTimeHistogram() {
   static const int kBuckets = 50;
 
   base::TimeTicks now = base::TimeTicks::Now();
-  if (!time_start_.is_null()) {
-    base::TimeDelta delta = now - time_start_;
+  if (!hash_dance_time_start_.is_null()) {
+    base::TimeDelta delta = now - hash_dance_time_start_;
     base::UmaHistogramCustomTimes(kUMAHashDanceSuccessTime + uma_suffix_, delta,
                                   kMin, kMax, kBuckets);
   }

chrome/browser/chromeos/policy/auto_enrollment_client_impl.h

@@ -258,6 +258,9 @@ class AutoEnrollmentClientImpl
 
   // Used to communicate with the device management service.
   DeviceManagementService* device_management_service_;
+  // Indicates whether Hash dance i.e. DeviceAutoEnrollmentRequest or
+  // DeviceStateRetrievalRequest is in progress. Note that is not affected by
+  // private set membership protocol, whether it's in progress or not.
   std::unique_ptr<DeviceManagementService::Job> request_job_;
 
   // PrefService where the protocol's results are cached.
@@ -279,10 +282,10 @@ class AutoEnrollmentClientImpl
 
   // Times used to determine the duration of the protocol, and the extra time
   // needed to complete after the signin was complete.
-  // If |time_start_| is not null, the protocol is still running.
+  // If |hash_dance_time_start_| is not null, the protocol is still running.
   // If |time_extra_start_| is not null, the protocol is still running but our
   // owner has relinquished ownership.
-  base::TimeTicks time_start_;
+  base::TimeTicks hash_dance_time_start_;
   base::TimeTicks time_extra_start_;
 
   // The time when the bucket download part of the protocol started.

chrome/browser/chromeos/policy/auto_enrollment_client_impl_unittest.cc

@@ -499,7 +499,8 @@ class AutoEnrollmentClientImplTest
     return static_cast<AutoEnrollmentClientImpl*>(client_.release());
   }
 
-  content::BrowserTaskEnvironment task_environment_;
+  content::BrowserTaskEnvironment task_environment_{
+      base::test::TaskEnvironment::TimeSource::MOCK_TIME};
   ScopedTestingLocalState scoped_testing_local_state_;
   TestingPrefServiceSimple* local_state_;
   std::unique_ptr<MockDeviceManagementService> service_;
@@ -1451,6 +1452,13 @@ class PrivateSetMembershipHelperTest : public AutoEnrollmentClientImplTest {
                            dummy_response);
   }
 
+  void ServerRepliesEmptyResponseForAsyncJob(
+      DeviceManagementService::JobControl** job) {
+    em::DeviceManagementResponse dummy_response;
+    ServerReplyForAsyncJob(job, net::OK, DeviceManagementService::kSuccess,
+                           dummy_response);
+  }
+
   // Mocks the server reply for the full controlled job |job|.
   void ServerReplyForAsyncJob(
       DeviceManagementService::JobControl** job,
@@ -1541,6 +1549,8 @@ class PrivateSetMembershipHelperTest : public AutoEnrollmentClientImplTest {
   PrivateSetMembershipHelperTest& operator=(
       const PrivateSetMembershipHelperTest&) = delete;
 
+  base::HistogramTester histogram_tester_;
+
  private:
   em::DeviceManagementResponse GetPrivateSetMembershipOprfResponse() const {
     em::DeviceManagementResponse response;
@@ -1570,8 +1580,6 @@ class PrivateSetMembershipHelperTest : public AutoEnrollmentClientImplTest {
       private_set_membership_last_job_type_ =
           DeviceManagementService::JobConfiguration::TYPE_INVALID;
   em::DeviceManagementRequest private_set_membership_last_request_;
-
-  base::HistogramTester histogram_tester_;
 };
 
 TEST_P(PrivateSetMembershipHelperTest, MembershipRetrievedSuccessfully) {
@@ -2213,6 +2221,8 @@ TEST_P(PrivateSetMembershipHelperAndHashDanceTest,
        RetryWhileWaitingForPrivateSetMembershipQueryResponseAndHashDanceFails) {
   InSequence sequence;
 
+  const base::TimeDelta kOneSecondTimeDelta = base::TimeDelta::FromSeconds(1);
+
   DeviceManagementService::JobControl* psm_rlwe_oprf_job = nullptr;
   DeviceManagementService::JobControl* psm_rlwe_query_job = nullptr;
   DeviceManagementService::JobControl* hash_dance_job = nullptr;
@@ -2242,6 +2252,9 @@ TEST_P(PrivateSetMembershipHelperAndHashDanceTest,
   ServerReplyForPrivateSetMembershipAsyncJobWithOprfResponse(
       &psm_rlwe_oprf_job);
 
+  // Advance the time forward one second.
+  task_environment_.FastForwardBy(kOneSecondTimeDelta);
+
   // Verify the only job that has been captured is the PSM RLWE Query request.
   VerifyPrivateSetMembershipRlweQueryRequest();
   VerifyPrivateSetMembershipLastRequestJobType();
@@ -2258,6 +2271,9 @@ TEST_P(PrivateSetMembershipHelperAndHashDanceTest,
   ServerReplyForPrivateSetMembershipAsyncJobWithQueryResponse(
       &psm_rlwe_query_job);
 
+  // Advance the time forward one second.
+  task_environment_.FastForwardBy(kOneSecondTimeDelta);
+
   // Verify private set membership result.
   EXPECT_EQ(GetStateDiscoveryResult(),
             GetExpectedMembershipResult()
@@ -2273,8 +2289,15 @@ TEST_P(PrivateSetMembershipHelperAndHashDanceTest,
   EXPECT_EQ(DeviceManagementService::JobConfiguration::TYPE_AUTO_ENROLLMENT,
             last_async_job_type_);
 
-  // Fail for DeviceAutoEnrollmentRequest i.e. hash dance request.
-  ServerFailsForAsyncJob(&hash_dance_job);
+  // Fail for DeviceAutoEnrollmentRequest i.e. hash dance request by sending
+  // an empty response.
+  ServerRepliesEmptyResponseForAsyncJob(&hash_dance_job);
+
+  // Verify Hash dance execution time histogram was recorded correctly.
+  const std::string kUMAHashDanceProtocolTimeStr = kUMAHashDanceProtocolTime;
+  histogram_tester_.ExpectUniqueTimeSample(
+      kUMAHashDanceProtocolTimeStr + kUMAHashDanceSuffixInitialEnrollment,
+      kOneSecondTimeDelta, /*expected_count=*/1);
 
   // Verify failure of Hash dance by inexistence of its cached decision.
   EXPECT_FALSE(HasCachedDecision());