Wire NetLog into the TreeStateTracker

components/certificate_transparency/single_tree_tracker.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 "components/certificate_transparency/single_tree_tracker.h"
 
 #include <algorithm>
 #include <iterator>
 #include <list>
 #include <utility>
 
 #include "base/bind.h"
 #include "base/metrics/histogram_macros.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/values.h"
 #include "components/certificate_transparency/log_dns_client.h"
 #include "crypto/sha2.h"
 #include "net/base/hash_value.h"
 #include "net/base/net_errors.h"
 #include "net/cert/ct_log_verifier.h"
 #include "net/cert/merkle_audit_proof.h"
 #include "net/cert/merkle_tree_leaf.h"
 #include "net/cert/signed_certificate_timestamp.h"
 #include "net/cert/x509_certificate.h"
+#include "net/log/net_log.h"
 
 using net::SHA256HashValue;
 using net::ct::LogEntry;
 using net::ct::MerkleAuditProof;
 using net::ct::MerkleTreeLeaf;
 using net::ct::SignedCertificateTimestamp;
 using net::ct::SignedTreeHead;
 
 // Overview of the process for auditing CT log entries
 //
@@ skipping 126 matching lines @@
 constexpr base::TimeDelta kMaximumMergeDelay = base::TimeDelta::FromHours(24);
 
 // The log MUST incorporate the a certificate in the tree within the Maximum
 // Merge Delay, so an entry can be audited once the timestamp from the SCT +
 // MMD has passed.
 // Returns true if the timestamp from the STH is newer than SCT timestamp + MMD.
 bool IsSCTReadyForAudit(base::Time sth_timestamp, base::Time sct_timestamp) {
   return sct_timestamp + kMaximumMergeDelay < sth_timestamp;
 }
 
+std::unique_ptr<base::Value> NetLogEntryAuditingEventCallback(
+    const SHA256HashValue* log_entry,
+    base::StringPiece log_id,
+    bool success,
+    net::NetLogCaptureMode capture_mode) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+
+  dict->SetString("log_entry",
+                  base::HexEncode(log_entry->data, crypto::kSHA256Length));
+  dict->SetString("log_id", base::HexEncode(log_id.data(), log_id.size()));
+  dict->SetBoolean("success", success);
+
+  return std::move(dict);
+}
+
 }  // namespace
 
 // The entry that is being audited.
 struct SingleTreeTracker::EntryToAudit {
   base::Time sct_timestamp;
   SHA256HashValue leaf_hash;
 
   explicit EntryToAudit(base::Time timestamp) : sct_timestamp(timestamp) {}
 };
 
@@ skipping 28 matching lines @@
     const EntryToAudit& lhs,
     const EntryToAudit& rhs) const {
   if (lhs.sct_timestamp != rhs.sct_timestamp)
     return lhs.sct_timestamp < rhs.sct_timestamp;
 
   return net::SHA256HashValueLessThan()(lhs.leaf_hash, rhs.leaf_hash);
 }
 
 SingleTreeTracker::SingleTreeTracker(
     scoped_refptr<const net::CTLogVerifier> ct_log,
-    LogDnsClient* dns_client)
+    LogDnsClient* dns_client,
+    net::NetLog* net_log)
     : ct_log_(std::move(ct_log)),
       checked_entries_(kCheckedEntriesCacheSize),
       dns_client_(dns_client),
+      net_log_(net::NetLogWithSource::Make(
+          net_log,
+          net::NetLogSourceType::CT_TREE_STATE_TRACKER)),
       weak_factory_(this) {
   memory_pressure_listener_.reset(new base::MemoryPressureListener(base::Bind(
       &SingleTreeTracker::OnMemoryPressure, base::Unretained(this))));
 }
 
 SingleTreeTracker::~SingleTreeTracker() {}
 
 void SingleTreeTracker::OnSCTVerified(net::X509Certificate* cert,
                                       const SignedCertificateTimestamp* sct) {
   DCHECK_EQ(ct_log_->key_id(), sct->log_id);
@@ skipping 130 matching lines @@
       it->second.state = INCLUSION_PROOF_REQUESTED;
     } else if (result == net::ERR_TEMPORARILY_THROTTLED) {
       dns_client_->NotifyWhenNotThrottled(
           base::Bind(&SingleTreeTracker::ProcessPendingEntries,
                      weak_factory_.GetWeakPtr()));
       // Exit the loop since all subsequent calls to QueryAuditProof
       // will be throttled.
       break;
     } else if (result == net::ERR_NAME_RESOLUTION_FAILED) {
       LogInclusionCheckResult(DNS_QUERY_NOT_POSSIBLE);
+      LogAuditResultToNetLog(it->first, false);
       // Lookup failed due to bad DNS configuration, erase the entry and
       // continue to the next one.
       it = pending_entries_.erase(it);
       // Break here if it's the last entry to avoid |it| being incremented
       // by the for loop.
       if (it == pending_entries_.end())
         break;
     } else {
       // BUG: an invalid argument was provided or an unexpected error
       // was returned from LogDnsClient.
@@ skipping 31 matching lines @@
                                              int net_error) {
   auto it = pending_entries_.find(entry);
   // The entry may not be present if it was evacuated due to low memory
   // pressure.
   if (it == pending_entries_.end())
     return;
 
   DCHECK_EQ(it->second.state, INCLUSION_PROOF_REQUESTED);
 
   if (net_error != net::OK) {
     // XXX(eranm): Should failures be cached? For now, they are not.

[eroman, 2017/01/31 19:24:25]

Can you update this to TODO(eranm) ?

[Eran Messeri, 2017/01/31 21:18:25]

Done.

     LogInclusionCheckResult(FAILED_GETTING_INCLUSION_PROOF);
+    LogAuditResultToNetLog(entry, false);
     pending_entries_.erase(it);
     return;
   }
 
   std::string leaf_hash(reinterpret_cast<const char*>(entry.leaf_hash.data),
                         crypto::kSHA256Length);
 
   bool verified = ct_log_->VerifyAuditProof(it->second.proof,
                                             it->second.root_hash, leaf_hash);
+  LogAuditResultToNetLog(entry, verified);
 
   if (!verified) {
     LogInclusionCheckResult(GOT_INVALID_INCLUSION_PROOF);
   } else {
     LogInclusionCheckResult(GOT_VALID_INCLUSION_PROOF);
     checked_entries_.Put(entry.leaf_hash, EntryAuditResult());
   }
 
   pending_entries_.erase(it);
 }
 
 void SingleTreeTracker::OnMemoryPressure(
     base::MemoryPressureListener::MemoryPressureLevel memory_pressure_level) {
   switch (memory_pressure_level) {
     case base::MemoryPressureListener::MEMORY_PRESSURE_LEVEL_NONE:
       break;
     case base::MemoryPressureListener::MEMORY_PRESSURE_LEVEL_CRITICAL:
       pending_entries_.clear();
     // Fall through to clearing the other cache.
     case base::MemoryPressureListener::MEMORY_PRESSURE_LEVEL_MODERATE:
       checked_entries_.Clear();
       break;
   }
 }
 
+void SingleTreeTracker::LogAuditResultToNetLog(const EntryToAudit& entry,
+                                               bool success) {
+  net::NetLogParametersCallback net_log_callback =
+      base::Bind(&NetLogEntryAuditingEventCallback, &entry.leaf_hash,
+                 ct_log_->key_id(), success);
+
+  net_log_.AddEvent(net::NetLogEventType::CT_LOG_ENTRY_AUDITED,
+                    net_log_callback);
+}
+
 }  // namespace certificate_transparency