Wire NetLog into the TreeStateTracker

components/certificate_transparency/single_tree_tracker_unittest.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 <string>
 #include <utility>
 
 #include "base/memory/ptr_util.h"
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/strings/string_piece.h"
 #include "base/test/histogram_tester.h"
 #include "components/base32/base32.h"
 #include "components/certificate_transparency/log_dns_client.h"
 #include "components/certificate_transparency/mock_log_dns_traffic.h"
 #include "crypto/sha2.h"
 #include "net/base/network_change_notifier.h"
 #include "net/cert/ct_log_verifier.h"
 #include "net/cert/ct_serialization.h"
 #include "net/cert/merkle_tree_leaf.h"
 #include "net/cert/signed_certificate_timestamp.h"
 #include "net/cert/signed_tree_head.h"
 #include "net/cert/x509_certificate.h"
 #include "net/dns/dns_client.h"
 #include "net/log/net_log.h"
+#include "net/log/test_net_log.h"
+#include "net/log/test_net_log_util.h"
 #include "net/test/ct_test_util.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using net::ct::SignedCertificateTimestamp;
 using net::ct::SignedTreeHead;
 using net::ct::GetSampleSignedTreeHead;
 using net::ct::GetTestPublicKeyId;
 using net::ct::GetTestPublicKey;
 using net::ct::kSthRootHashLength;
 using net::ct::GetX509CertSCT;
@@ skipping 40 matching lines @@
 
 scoped_refptr<SignedCertificateTimestamp> GetSCT() {
   scoped_refptr<SignedCertificateTimestamp> sct;
 
   // TODO(eranm): Move setting of the origin field to ct_test_util.cc
   GetX509CertSCT(&sct);
   sct->origin = SignedCertificateTimestamp::SCT_FROM_OCSP_RESPONSE;
   return sct;
 }
 
-std::string Base32LeafHash(const net::X509Certificate* cert,
-                           const SignedCertificateTimestamp* sct) {
+std::string LeafHash(const net::X509Certificate* cert,
+                     const SignedCertificateTimestamp* sct) {
   net::ct::MerkleTreeLeaf leaf;
   if (!GetMerkleTreeLeaf(cert, sct, &leaf))
     return std::string();
 
   std::string leaf_hash;
   if (!HashMerkleTreeLeaf(leaf, &leaf_hash))
     return std::string();
 
+  return leaf_hash;
+}
+
+std::string Base32LeafHash(const net::X509Certificate* cert,
+                           const SignedCertificateTimestamp* sct) {
+  std::string leaf_hash = LeafHash(cert, sct);
+  if (leaf_hash.empty())
+    return std::string();
+
   return base32::Base32Encode(leaf_hash,
                               base32::Base32EncodePolicy::OMIT_PADDING);
 }
 
 // Fills in |sth| for a tree of size 2, where the root hash is a hash of
 // the test SCT (from GetX509CertSCT) and another entry,
 // whose hash is '0a' 32 times.
 bool GetSignedTreeHeadForTreeOfSize2(SignedTreeHead* sth) {
   sth->version = SignedTreeHead::V1;
   // Timestamp is after the timestamp of the test SCT (GetX509CertSCT)
@@ skipping 59 matching lines @@
     cert_sct_->origin = SignedCertificateTimestamp::SCT_FROM_OCSP_RESPONSE;
 
     net_change_notifier_ =
         base::WrapUnique(net::NetworkChangeNotifier::CreateMock());
     mock_dns_.InitializeDnsConfig();
   }
 
  protected:
   void CreateTreeTracker() {
     log_dns_client_ = base::MakeUnique<LogDnsClient>(
-        mock_dns_.CreateDnsClient(), net_log_, 1);
+        mock_dns_.CreateDnsClient(), net_log_with_source_, 1);
 
-    tree_tracker_ =
-        base::MakeUnique<SingleTreeTracker>(log_, log_dns_client_.get());
+    tree_tracker_ = base::MakeUnique<SingleTreeTracker>(
+        log_, log_dns_client_.get(), &net_log_);
   }
 
   void CreateTreeTrackerWithDefaultDnsExpectation() {
     // Default to throttling requests as it means observed log entries will
     // be frozen in a pending state, simplifying testing of the
     // SingleTreeTracker.
     ASSERT_TRUE(ExpectLeafIndexRequestAndThrottle(chain_, cert_sct_));
     CreateTreeTracker();
   }
 
   // Configured the |mock_dns_| to expect a request for the leaf index
   // and have th mock DNS client throttle it.
   bool ExpectLeafIndexRequestAndThrottle(
       const scoped_refptr<net::X509Certificate>& chain,
       const scoped_refptr<SignedCertificateTimestamp>& sct) {
     return mock_dns_.ExpectRequestAndSocketError(
         Base32LeafHash(chain.get(), sct.get()) + ".hash." + kDNSRequestSuffix,
         net::Error::ERR_TEMPORARILY_THROTTLED);
   }
 
+  bool MatchAuditingResultInNetLog(net::TestNetLog& net_log,
+                                   std::string expected_leaf_hash,
+                                   bool expected_success) {
+    net::TestNetLogEntry::List entries;
+
+    net_log.GetEntries(&entries);
+    if (entries.size() == 0)
+      return false;
+
+    size_t pos = net::ExpectLogContainsSomewhere(
+        entries, 0, net::NetLogEventType::CT_LOG_ENTRY_AUDITED,
+        net::NetLogEventPhase::NONE);
+
+    const net::TestNetLogEntry& logged_entry = entries[pos];
+
+    std::string logged_log_id, logged_leaf_hash;
+    if (!logged_entry.GetStringValue("log_id", &logged_log_id) ||
+        !logged_entry.GetStringValue("log_entry", &logged_leaf_hash))
+      return false;
+
+    if (base::HexEncode(GetTestPublicKeyId().data(),
+                        GetTestPublicKeyId().size()) != logged_log_id)
+      return false;
+
+    if (base::HexEncode(expected_leaf_hash.data(), expected_leaf_hash.size()) !=
+        logged_leaf_hash)
+      return false;
+
+    bool logged_success;
+    if (!logged_entry.GetBooleanValue("success", &logged_success))
+      return false;
+
+    return logged_success == expected_success;
+  }
+
   base::MessageLoopForIO message_loop_;
   MockLogDnsTraffic mock_dns_;
   scoped_refptr<const net::CTLogVerifier> log_;
   std::unique_ptr<net::NetworkChangeNotifier> net_change_notifier_;
   std::unique_ptr<LogDnsClient> log_dns_client_;
   std::unique_ptr<SingleTreeTracker> tree_tracker_;
   scoped_refptr<net::X509Certificate> chain_;
   scoped_refptr<SignedCertificateTimestamp> cert_sct_;
-  net::NetLogWithSource net_log_;
+  net::TestNetLog net_log_;
+  net::NetLogWithSource net_log_with_source_;
 };
 
 // Test that an SCT is classified as pending for a newer STH if the
 // SingleTreeTracker has not seen any STHs so far.
 TEST_F(SingleTreeTrackerTest, CorrectlyClassifiesUnobservedSCTNoSTH) {
   CreateTreeTrackerWithDefaultDnsExpectation();
 
   base::HistogramTester histograms;
   // First make sure the SCT has not been observed at all.
   EXPECT_EQ(
       SingleTreeTracker::SCT_NOT_OBSERVED,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
 
   tree_tracker_->OnSCTVerified(chain_.get(), cert_sct_.get());
 
   // Since no STH was provided to the tree_tracker_ the status should be that
   // the SCT is pending a newer STH.
   EXPECT_EQ(
       SingleTreeTracker::SCT_PENDING_NEWER_STH,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
 
   // Expect logging of a value indicating a valid STH is required.
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 1);
   histograms.ExpectBucketCount(kCanCheckForInclusionHistogramName, 0, 1);
+  EXPECT_EQ(0u, net_log_.GetSize());
 }
 
 // Test that an SCT is classified as pending an inclusion check if the
 // SingleTreeTracker has a fresh-enough STH to check inclusion against.
 TEST_F(SingleTreeTrackerTest, CorrectlyClassifiesUnobservedSCTWithRecentSTH) {
   CreateTreeTrackerWithDefaultDnsExpectation();
 
   base::HistogramTester histograms;
   // Provide an STH to the tree_tracker_.
   SignedTreeHead sth;
@@ skipping 15 matching lines @@
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
 
   // Exactly one value should be logged, indicating the SCT can be checked for
   // inclusion, as |tree_tracker_| did have a valid STH when it was notified
   // of a new SCT.
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 1);
   histograms.ExpectBucketCount(kCanCheckForInclusionHistogramName, 2, 1);
   // Nothing should be logged in the result histogram since inclusion check
   // didn't finish.
   histograms.ExpectTotalCount(kInclusionCheckResultHistogramName, 0);
+  EXPECT_EQ(0u, net_log_.GetSize());
 }
 
 // Test that the SingleTreeTracker correctly queues verified SCTs for inclusion
 // checking such that, upon receiving a fresh STH, it changes the SCT's status
 // from pending newer STH to pending inclusion check.
 TEST_F(SingleTreeTrackerTest, CorrectlyUpdatesSCTStatusOnNewSTH) {
   CreateTreeTrackerWithDefaultDnsExpectation();
 
   base::HistogramTester histograms;
   // Report an observed SCT and make sure it's in the pending newer STH
@@ skipping 10 matching lines @@
   tree_tracker_->NewSTHObserved(sth);
 
   // Test that its status has changed.
   EXPECT_EQ(
       SingleTreeTracker::SCT_PENDING_INCLUSION_CHECK,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
   // Check that no additional UMA was logged for this case as the histogram is
   // only supposed to measure the state of newly-observed SCTs, not pending
   // ones.
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 1);
+  EXPECT_EQ(0u, net_log_.GetSize());
 }
 
 // Test that the SingleTreeTracker does not change an SCT's status if an STH
 // from the log it was issued by is observed, but that STH is too old to check
 // inclusion against.
 TEST_F(SingleTreeTrackerTest, DoesNotUpdatesSCTStatusOnOldSTH) {
   CreateTreeTrackerWithDefaultDnsExpectation();
 
   // Notify of an SCT and make sure it's in the 'pending newer STH' state.
   tree_tracker_->OnSCTVerified(chain_.get(), cert_sct_.get());
   EXPECT_EQ(
       SingleTreeTracker::SCT_PENDING_NEWER_STH,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
 
   // Provide an old STH for the same log.
   SignedTreeHead sth;
   GetOldSignedTreeHead(&sth);
   tree_tracker_->NewSTHObserved(sth);
 
   // Make sure the SCT's state hasn't changed.
   EXPECT_EQ(
       SingleTreeTracker::SCT_PENDING_NEWER_STH,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
+  EXPECT_EQ(0u, net_log_.GetSize());
 }
 
 // Test that the SingleTreeTracker correctly logs that an SCT is pending a new
 // STH, when it has a valid STH,  but the observed SCT is not covered by the
 // STH.
 TEST_F(SingleTreeTrackerTest, LogsUMAForNewSCTAndOldSTH) {
   CreateTreeTrackerWithDefaultDnsExpectation();
 
   base::HistogramTester histograms;
   // Provide an old STH for the same log.
   SignedTreeHead sth;
   GetOldSignedTreeHead(&sth);
   tree_tracker_->NewSTHObserved(sth);
 
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 0);
 
   // Notify of an SCT and make sure it's in the 'pending newer STH' state.
   tree_tracker_->OnSCTVerified(chain_.get(), cert_sct_.get());
 
   // Exactly one value should be logged, indicating the SCT cannot be checked
   // for inclusion as the STH is too old.
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 1);
   histograms.ExpectBucketCount(kCanCheckForInclusionHistogramName, 1, 1);
+  EXPECT_EQ(0u, net_log_.GetSize());
 }
 
 // Test that an entry transitions to the "not found" state if the LogDnsClient
 // fails to get a leaf index.
 TEST_F(SingleTreeTrackerTest, TestEntryNotPendingAfterLeafIndexFetchFailure) {
   ASSERT_TRUE(mock_dns_.ExpectRequestAndSocketError(
       Base32LeafHash(chain_.get(), cert_sct_.get()) + ".hash." +
           kDNSRequestSuffix,
       net::Error::ERR_FAILED));
 
   CreateTreeTracker();
 
   tree_tracker_->OnSCTVerified(chain_.get(), cert_sct_.get());
   EXPECT_EQ(
       SingleTreeTracker::SCT_PENDING_NEWER_STH,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
 
   // Provide with a fresh STH
   SignedTreeHead sth;
   GetSampleSignedTreeHead(&sth);
   tree_tracker_->NewSTHObserved(sth);
   base::RunLoop().RunUntilIdle();
 
   EXPECT_EQ(
       SingleTreeTracker::SCT_NOT_OBSERVED,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
+  // There should have been one NetLog event, logged with failure.
+  EXPECT_TRUE(MatchAuditingResultInNetLog(
+      net_log_, LeafHash(chain_.get(), cert_sct_.get()), false));
 }
 
 // Test that an entry transitions to the "not found" state if the LogDnsClient
 // succeeds to get a leaf index but fails to get an inclusion proof.
 TEST_F(SingleTreeTrackerTest, TestEntryNotPendingAfterInclusionCheckFailure) {
   // Return 12 as the index of this leaf.
   ASSERT_TRUE(mock_dns_.ExpectLeafIndexRequestAndResponse(
       Base32LeafHash(chain_.get(), cert_sct_.get()) + ".hash." +
           kDNSRequestSuffix,
       12));
@@ skipping 13 matching lines @@
 
   // Provide with a fresh STH
   SignedTreeHead sth;
   GetSampleSignedTreeHead(&sth);
   tree_tracker_->NewSTHObserved(sth);
   base::RunLoop().RunUntilIdle();
 
   EXPECT_EQ(
       SingleTreeTracker::SCT_NOT_OBSERVED,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
+  // There should have been one NetLog event, logged with failure.
+  EXPECT_TRUE(MatchAuditingResultInNetLog(
+      net_log_, LeafHash(chain_.get(), cert_sct_.get()), false));
 }
 
 // Test that an entry transitions to the "included" state if the LogDnsClient
 // succeeds to get a leaf index and an inclusion proof.
 TEST_F(SingleTreeTrackerTest, TestEntryIncludedAfterInclusionCheckSuccess) {
   std::vector<std::string> audit_proof;
   FillVectorWithValidAuditProofForTreeOfSize2(&audit_proof);
 
   // Return 0 as the index for this leaf, so the proof provided
   // later on would verify.
@@ skipping 19 matching lines @@
   SignedTreeHead sth;
   ASSERT_TRUE(GetSignedTreeHeadForTreeOfSize2(&sth));
   ASSERT_TRUE(log_->VerifySignedTreeHead(sth));
 
   tree_tracker_->NewSTHObserved(sth);
   base::RunLoop().RunUntilIdle();
 
   EXPECT_EQ(
       SingleTreeTracker::SCT_INCLUDED_IN_LOG,
       tree_tracker_->GetLogEntryInclusionStatus(chain_.get(), cert_sct_.get()));
+  // There should have been one NetLog event, with success logged.
+  EXPECT_TRUE(MatchAuditingResultInNetLog(
+      net_log_, LeafHash(chain_.get(), cert_sct_.get()), true));
 }
 
 // Test that pending entries transition states correctly according to the
 // STHs provided:
 // * Start without an STH.
 // * Add a collection of entries with mixed timestamps (i.e. SCTs not added
 //   in the order of their timestamps).
 // * Provide an STH that covers some of the entries, test these are audited.
 // * Provide another STH that covers more of the entries, test that the entries
 //   already audited are not audited again and that those that need to be
@@ skipping 199 matching lines @@
   // inclusion, as |tree_tracker_| did have a valid STH when it was notified
   // of a new SCT.
   histograms.ExpectTotalCount(kCanCheckForInclusionHistogramName, 1);
   histograms.ExpectBucketCount(kCanCheckForInclusionHistogramName, 2, 1);
   // Failure due to DNS configuration should be logged in the result histogram.
   histograms.ExpectTotalCount(kInclusionCheckResultHistogramName, 1);
   histograms.ExpectBucketCount(kInclusionCheckResultHistogramName, 3, 1);
 }
 
 }  // namespace certificate_transparency