UMA metrics for LogDnsClient

components/certificate_transparency/log_dns_client.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/log_dns_client.h"
 
 #include "base/bind.h"
 #include "base/callback_helpers.h"
 #include "base/format_macros.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "components/base32/base32.h"
 #include "crypto/sha2.h"
 #include "net/cert/merkle_audit_proof.h"
 #include "net/dns/dns_client.h"
 #include "net/dns/dns_config_service.h"
 #include "net/dns/dns_protocol.h"
 #include "net/dns/dns_response.h"
 #include "net/dns/dns_transaction.h"
 #include "net/dns/record_parsed.h"
 #include "net/dns/record_rdata.h"
 
 namespace certificate_transparency {
 
 namespace {
 
+// Used by UMA_HISTOGRAM_ENUMERATION to record query success/failures.
+// These values are written to logs.  New enum values can be added, but existing
+// enums must never be renumbered or deleted and reused.
+enum QueryStatus {
+  QUERY_STATUS_SUCCESS = 0,
+  QUERY_STATUS_FAILED_MISC = 1,

[Eran Messeri, 2016/12/20 11:41:54]

Nit: Rename FAILED_MISC to FAILED_UNKNOWN / FAILED_OTHER_DNS_ERROR ?
MISC is a bit too general a name, but I don't have a better suggestion.

[Rob Percival, 2016/12/21 15:30:51]

Done.

+  QUERY_STATUS_FAILED_NAME_RESOLUTION = 2,
+  QUERY_STATUS_FAILED_LEAF_INDEX_MALFORMED = 3,
+  QUERY_STATUS_FAILED_INCLUSION_PROOF_MALFORMED = 4,
+  QUERY_STATUS_MAX  // Upper bound
+};
+
+void LogQueryStatus(QueryStatus result) {
+  UMA_HISTOGRAM_ENUMERATION("Net.CertificateTransparency.DnsQueryStatus",
+                            result, QUERY_STATUS_MAX);
+}
+
+void LogQueryDuration(const base::TimeDelta& duration) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("Net.CertificateTransparency.DnsQueryDuration",
+                             duration);
+}
+
 // Parses the DNS response and extracts a single string from the TXT RDATA.
 // If the response is malformed, not a TXT record, or contains any number of
 // strings other than 1, this returns false and extracts nothing.
 // Otherwise, it returns true and the extracted string is assigned to |*txt|.
 bool ParseTxtResponse(const net::DnsResponse& response, std::string* txt) {
   DCHECK(txt);
 
   net::DnsRecordParser parser = response.Parser();
   // We don't care about the creation time, since we're going to throw
   // |parsed_record| away as soon as we've extracted the payload, so provide
@@ skipping 141 matching lines @@
   net::CompletionCallback callback_;
   // The DnsClient to use for sending DNS requests to the CT log.
   net::DnsClient* dns_client_;
   // The most recent DNS request. Null if no DNS requests have been made.
   std::unique_ptr<net::DnsTransaction> current_dns_transaction_;
   // The most recent DNS response. Only valid so long as the corresponding DNS
   // request is stored in |current_dns_transaction_|.
   const net::DnsResponse* last_dns_response_;
   // The NetLog that DNS transactions will log to.
   net::NetLogWithSource net_log_;
+  // The time that Start() was last called. Used to measure query duration.
+  base::TimeTicks start_time_;
   // Produces WeakPtrs to |this| for binding callbacks.
   base::WeakPtrFactory<AuditProofQuery> weak_ptr_factory_;
 };
 
 LogDnsClient::AuditProofQuery::AuditProofQuery(
     net::DnsClient* dns_client,
     const std::string& domain_for_log,
     const net::NetLogWithSource& net_log)
     : next_state_(State::NONE),
       domain_for_log_(domain_for_log),
       dns_client_(dns_client),
       net_log_(net_log),
       weak_ptr_factory_(this) {
   DCHECK(dns_client_);
   DCHECK(!domain_for_log_.empty());
 }
 
 // |leaf_hash| is not a const-ref to allow callers to std::move that string into
 // the method, avoiding the need to make a copy.
 net::Error LogDnsClient::AuditProofQuery::Start(
     std::string leaf_hash,
     uint64_t tree_size,
     const net::CompletionCallback& callback,
     net::ct::MerkleAuditProof* proof) {
   // It should not already be in progress.
   DCHECK_EQ(State::NONE, next_state_);
+  start_time_ = base::TimeTicks::Now();
   proof_ = proof;
   proof_->tree_size = tree_size;
   leaf_hash_ = std::move(leaf_hash);
   callback_ = callback;
   // The first step in the query is to request the leaf index corresponding to
   // |leaf_hash| from the CT log.
   next_state_ = State::REQUEST_LEAF_INDEX;
   // Begin the state machine.
   return DoLoop(net::OK);
 }
 
 net::Error LogDnsClient::AuditProofQuery::DoLoop(net::Error result) {
   CHECK_NE(State::NONE, next_state_);
+  State state;
   do {
-    State state = next_state_;
+    state = next_state_;
     next_state_ = State::NONE;
     switch (state) {
       case State::REQUEST_LEAF_INDEX:
         result = RequestLeafIndex();
         break;
       case State::REQUEST_LEAF_INDEX_COMPLETE:
         result = RequestLeafIndexComplete(result);
         break;
       case State::REQUEST_AUDIT_PROOF_NODES:
         result = RequestAuditProofNodes();
         break;
       case State::REQUEST_AUDIT_PROOF_NODES_COMPLETE:
         result = RequestAuditProofNodesComplete(result);
         break;
       case State::NONE:
         NOTREACHED();
         break;
     }
   } while (result != net::ERR_IO_PENDING && next_state_ != State::NONE);
 
+  if (result != net::ERR_IO_PENDING) {
+    // If the query is complete, log some metrics.
+    LogQueryDuration(base::TimeTicks::Now() - start_time_);
+
+    switch (result) {
+      case net::OK:
+        LogQueryStatus(QUERY_STATUS_SUCCESS);
+        break;
+      case net::ERR_NAME_RESOLUTION_FAILED:
+        LogQueryStatus(QUERY_STATUS_FAILED_NAME_RESOLUTION);
+        break;
+      case net::ERR_DNS_MALFORMED_RESPONSE:
+        switch (state) {
+          case State::REQUEST_LEAF_INDEX_COMPLETE:
+            LogQueryStatus(QUERY_STATUS_FAILED_LEAF_INDEX_MALFORMED);
+            break;
+          case State::REQUEST_AUDIT_PROOF_NODES_COMPLETE:
+            LogQueryStatus(QUERY_STATUS_FAILED_INCLUSION_PROOF_MALFORMED);
+            break;
+          default:
+            NOTREACHED();
+            LogQueryStatus(QUERY_STATUS_FAILED_MISC);

[Eran Messeri, 2016/12/20 11:41:54]

Nit: Don't log here, since it's unreachable code (and may be conflated with the
other case FAILED_MISC is logged anyway).

[Rob Percival, 2016/12/21 15:30:51]

Done.

+            break;
+        }
+        break;
+      default:
+        // Some other error occurred.
+        LogQueryStatus(QUERY_STATUS_FAILED_MISC);
+        break;
+    }
+  }
+
   return result;
 }
 
 void LogDnsClient::AuditProofQuery::OnDnsTransactionComplete(
     net::DnsTransaction* transaction,
     int net_error,
     const net::DnsResponse* response) {
   DCHECK_EQ(current_dns_transaction_.get(), transaction);
   last_dns_response_ = response;
   net::Error result = DoLoop(static_cast<net::Error>(net_error));
@@ skipping 205 matching lines @@
 }
 
 void LogDnsClient::UpdateDnsConfig() {
   net::DnsConfig config;
   net::NetworkChangeNotifier::GetDnsConfig(&config);
   if (config.IsValid())
     dns_client_->SetConfig(config);
 }
 
 }  // namespace certificate_transparency