PVer4: DecodeHashes needs to sort the output of the Rice decoder

components/safe_browsing_db/v4_store.cc

 // Copyright 2016 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.
 
 #include "base/base64.h"
 #include "base/bind.h"
 #include "base/files/file_util.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/metrics/sparse_histogram.h"
@@ skipping 184 matching lines @@
     expected_checksum = response->checksum().sha256();
   }
 
   apply_update_result = MergeUpdate(hash_prefix_map_old, hash_prefix_map,
                                     raw_removals, expected_checksum);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     return apply_update_result;
   }
 
   state_ = response->new_client_state();
+  DVLOG(1) << "Update successful: " << *this;

[Nathan Parker, 2016/08/12 23:01:49]

These are fairly verbose -- You should plan to remove most of them once the code
is stable.

[vakh (use Gerrit instead), 2016/08/13 00:15:14]

Ack. Done.
Also: http://crbug.com/637468

   return APPLY_UPDATE_SUCCESS;
 }
 
 void V4Store::ApplyUpdate(
     std::unique_ptr<ListUpdateResponse> response,
     const scoped_refptr<base::SingleThreadTaskRunner>& callback_task_runner,
     UpdatedStoreReadyCallback callback) {
+  DVLOG(1) << "ApplyUpdate: response_size: " << response->ByteSize() << " : "
+           << *this;
+
   std::unique_ptr<V4Store> new_store(
       new V4Store(this->task_runner_, this->store_path_));
 
   ApplyUpdateResult apply_update_result;
   if (response->response_type() == ListUpdateResponse::PARTIAL_UPDATE) {
     apply_update_result = new_store->ProcessPartialUpdateAndWriteToDisk(
         hash_prefix_map_, std::move(response));
   } else if (response->response_type() == ListUpdateResponse::FULL_UPDATE) {
     apply_update_result =
         new_store->ProcessFullUpdateAndWriteToDisk(std::move(response));
   } else {
     apply_update_result = UNEXPECTED_RESPONSE_TYPE_FAILURE;
-    NOTREACHED() << "Unexpected response type: " << response->response_type();
+    NOTREACHED() << "Failure: Unexpected response type: "
+                 << response->response_type();
   }
 
   if (apply_update_result == APPLY_UPDATE_SUCCESS) {
     // new_store is done updating, pass it to the callback.
     callback_task_runner->PostTask(
         FROM_HERE, base::Bind(callback, base::Passed(&new_store)));
   } else {
-    DVLOG(1) << "ApplyUpdate failed: reason: " << apply_update_result
+    DVLOG(1) << "Failure: ApplyUpdate: reason: " << apply_update_result
              << "; store: " << *this;
     // new_store failed updating. Pass a nullptr to the callback.
     callback_task_runner->PostTask(FROM_HERE, base::Bind(callback, nullptr));
   }
 
   RecordApplyUpdateResult(apply_update_result);
 }
 
 // static
 ApplyUpdateResult V4Store::UpdateHashPrefixMapFromAdditions(
@@ skipping 51 matching lines @@
     NOTREACHED();
     return PREFIX_SIZE_TOO_SMALL_FAILURE;
   }
   if (prefix_size > kMaxHashPrefixLength) {
     NOTREACHED();
     return PREFIX_SIZE_TOO_LARGE_FAILURE;
   }
   if (lumped_hashes.size() % prefix_size != 0) {
     return ADDITIONS_SIZE_UNEXPECTED_FAILURE;
   }
+
   // TODO(vakh): Figure out a way to avoid the following copy operation.
   (*additions_map)[prefix_size] = lumped_hashes;
   return APPLY_UPDATE_SUCCESS;
 }
 
 // static
 bool V4Store::GetNextSmallestUnmergedPrefix(
     const HashPrefixMap& hash_prefix_map,
     const IteratorMap& iterator_map,
     HashPrefix* smallest_hash_prefix) {
@@ skipping 74 matching lines @@
   // to determine which elements to drop based on the raw_removals. Note that
   // picked is not the same as merged. A picked element isn't merged if its
   // index is on the raw_removals list.
   int total_picked_from_old = 0;
   const int* removals_iter = raw_removals ? raw_removals->begin() : nullptr;
   while (old_has_unmerged || additions_has_unmerged) {
     // If the same hash prefix appears in the existing store and the additions
     // list, something is clearly wrong. Discard the update.
     if (old_has_unmerged && additions_has_unmerged &&
         next_smallest_prefix_old == next_smallest_prefix_additions) {
+      DVLOG(1) << "Failure: ADDITIONS_HAS_EXISTING_PREFIX_FAILURE";

[Nathan Parker, 2016/08/12 23:01:49]

Can you log this further up instead?  Just logging the enum # is usually
sufficient, since it should be rarely used.

Same with those below.

[vakh (use Gerrit instead), 2016/08/13 00:15:14]

Done.

       return ADDITIONS_HAS_EXISTING_PREFIX_FAILURE;
     }
 
     // Select which map to pick the next hash prefix from to keep the result in
     // lexographically sorted order.
     bool pick_from_old =
         old_has_unmerged &&
         (!additions_has_unmerged ||
          (next_smallest_prefix_old < next_smallest_prefix_additions));
 
@@ skipping 42 matching lines @@
           next_smallest_prefix_size;
 
       // Find the next smallest unmerged element in the additions map.
       additions_has_unmerged =
           GetNextSmallestUnmergedPrefix(additions_map, additions_iterator_map,
                                         &next_smallest_prefix_additions);
     }
   }
 
   if (raw_removals && removals_iter != raw_removals->end()) {
+    DVLOG(1) << "Failure: REMOVALS_INDEX_TOO_LARGE_FAILURE";
     return REMOVALS_INDEX_TOO_LARGE_FAILURE;
   }
 
   if (calculate_checksum) {
     std::string checksum(crypto::kSHA256Length, 0);
     checksum_ctx->Finish(string_as_array(&checksum), checksum.size());
     if (checksum != expected_checksum) {
       std::string checksum_base64, expected_checksum_base64;
       base::Base64Encode(checksum, &checksum_base64);
       base::Base64Encode(expected_checksum, &expected_checksum_base64);
-      DVLOG(1) << "Checksum failed: calculated: " << checksum_base64
-               << "expected: " << expected_checksum_base64;
+      DVLOG(1) << "Failure: Checksum mismatch: calculated: " << checksum_base64
+               << " expected: " << expected_checksum_base64;
       return CHECKSUM_MISMATCH_FAILURE;
     }
   }
 
   return APPLY_UPDATE_SUCCESS;
 }
 
 StoreReadResult V4Store::ReadFromDisk() {
   DCHECK(task_runner_->RunsTasksOnCurrentThread());
 
   std::string contents;
   bool read_success = base::ReadFileToString(store_path_, &contents);
   if (!read_success) {
     return FILE_UNREADABLE_FAILURE;
   }
 
   if (contents.empty()) {
     return FILE_EMPTY_FAILURE;
   }
 
   V4StoreFileFormat file_format;
   if (!file_format.ParseFromString(contents)) {
     return PROTO_PARSING_FAILURE;
   }
 
   if (file_format.magic_number() != kFileMagic) {
-    DVLOG(1) << "Unexpected magic number found in file: "
+    DVLOG(1) << "Failure: Unexpected magic number found in file: "

[Nathan Parker, 2016/08/12 23:01:49]

These DVLOGs actually seem like more clutter than they're worth, since they just
mean the file is corrupted.  We don't need to maintain code to tell a developer
which part of the file is corrupted.

Same with file version and response type.  If someday we start getting those
errors, we can easily add a line to log it.

[vakh (use Gerrit instead), 2016/08/13 00:15:14]

Done.

              << file_format.magic_number();
     return UNEXPECTED_MAGIC_NUMBER_FAILURE;
   }
 
   UMA_HISTOGRAM_SPARSE_SLOWLY("SafeBrowsing.V4StoreVersionRead",
                               file_format.version_number());
   if (file_format.version_number() != kFileVersion) {
-    DVLOG(1) << "File version incompatible: " << file_format.version_number()
-             << "; expected: " << kFileVersion;
+    DVLOG(1) << "Failure: File version incompatible: "
+             << file_format.version_number() << "; expected: " << kFileVersion;
     return FILE_VERSION_INCOMPATIBLE_FAILURE;
   }
 
   if (!file_format.has_list_update_response()) {
     return HASH_PREFIX_INFO_MISSING_FAILURE;
   }
 
   std::unique_ptr<ListUpdateResponse> response(new ListUpdateResponse);
   response->Swap(file_format.mutable_list_update_response());
   ApplyUpdateResult apply_update_result = ProcessFullUpdate(response);
   RecordApplyUpdateResultWhenReadingFromDisk(apply_update_result);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     hash_prefix_map_.clear();
     return HASH_PREFIX_MAP_GENERATION_FAILURE;
   }
 
   return READ_SUCCESS;
 }
 
 StoreWriteResult V4Store::WriteToDisk(
     std::unique_ptr<ListUpdateResponse> response) const {
   // Do not write partial updates to the disk.
   // After merging the updates, the ListUpdateResponse passed to this method
   // should be a FULL_UPDATE.
   if (!response->has_response_type() ||
       response->response_type() != ListUpdateResponse::FULL_UPDATE) {
-    DVLOG(1) << "response->has_response_type(): "
-             << response->has_response_type();
-    DVLOG(1) << "response->response_type(): " << response->response_type();
+    DVLOG(1) << "Failure: response->has_response_type(): "
+             << response->has_response_type()
+             << " : response->response_type(): " << response->response_type();
     return INVALID_RESPONSE_TYPE_FAILURE;
   }
 
   // Attempt writing to a temporary file first and at the end, swap the files.
   const base::FilePath new_filename = TemporaryFileForFilename(store_path_);
 
   V4StoreFileFormat file_format;
   file_format.set_magic_number(kFileMagic);
   file_format.set_version_number(kFileVersion);
   ListUpdateResponse* response_to_write =
@@ skipping 46 matching lines @@
   if (result == 0) {
     return true;
   } else if (result < 0) {
     return HashPrefixMatches(hash_prefix, begin, mid);
   } else {
     return HashPrefixMatches(hash_prefix, mid + prefix_size, end);
   }
 }
 
 }  // namespace safe_browsing