Add quic_logging

net/quic/core/crypto/quic_crypto_server_config.cc

 // Copyright 2013 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 "net/quic/core/crypto/quic_crypto_server_config.h"
 
 #include <stdlib.h>
 
 #include <algorithm>
 #include <memory>
@@ skipping 18 matching lines @@
 #include "net/quic/core/crypto/quic_decrypter.h"
 #include "net/quic/core/crypto/quic_encrypter.h"
 #include "net/quic/core/crypto/quic_random.h"
 #include "net/quic/core/proto/source_address_token.pb.h"
 #include "net/quic/core/quic_flags.h"
 #include "net/quic/core/quic_packets.h"
 #include "net/quic/core/quic_socket_address_coder.h"
 #include "net/quic/core/quic_utils.h"
 #include "net/quic/platform/api/quic_bug_tracker.h"
 #include "net/quic/platform/api/quic_clock.h"
+#include "net/quic/platform/api/quic_logging.h"
 #include "net/quic/platform/api/quic_reference_counted.h"
 #include "net/quic/platform/api/quic_text_utils.h"
 
 using base::StringPiece;
 using crypto::SecureHash;
 using std::string;
 
 namespace net {
 
 namespace {
@@ skipping 244 matching lines @@
   return config;
 }
 
 CryptoHandshakeMessage* QuicCryptoServerConfig::AddConfig(
     std::unique_ptr<QuicServerConfigProtobuf> protobuf,
     const QuicWallTime now) {
   std::unique_ptr<CryptoHandshakeMessage> msg(
       CryptoFramer::ParseMessage(protobuf->config()));
 
   if (!msg.get()) {
-    LOG(WARNING) << "Failed to parse server config message";
+    QUIC_LOG(WARNING) << "Failed to parse server config message";
     return nullptr;
   }
 
   QuicReferenceCountedPointer<Config> config(ParseConfigProtobuf(protobuf));
   if (!config.get()) {
-    LOG(WARNING) << "Failed to parse server config message";
+    QUIC_LOG(WARNING) << "Failed to parse server config message";
     return nullptr;
   }
 
   {
     QuicWriterMutexLock locked(&configs_lock_);
     if (configs_.find(config->id) != configs_.end()) {
-      LOG(WARNING) << "Failed to add config because another with the same "
-                      "server config id already exists: "
-                   << QuicTextUtils::HexEncode(config->id);
+      QUIC_LOG(WARNING) << "Failed to add config because another with the same "
+                           "server config id already exists: "
+                        << QuicTextUtils::HexEncode(config->id);
       return nullptr;
     }
 
     configs_[config->id] = config;
     SelectNewPrimaryConfig(now);
     DCHECK(primary_config_.get());
     DCHECK_EQ(configs_.find(primary_config_->id)->second.get(),
               primary_config_.get());
   }
 
@@ skipping 17 matching lines @@
     QuicReferenceCountedPointer<Config> config(ParseConfigProtobuf(protobuf));
     if (!config) {
       ok = false;
       break;
     }
 
     parsed_configs.push_back(config);
   }
 
   if (parsed_configs.empty()) {
-    LOG(WARNING) << "New config list is empty.";
+    QUIC_LOG(WARNING) << "New config list is empty.";
     ok = false;
   }
 
   if (!ok) {
-    LOG(WARNING) << "Rejecting QUIC configs because of above errors";
+    QUIC_LOG(WARNING) << "Rejecting QUIC configs because of above errors";
   } else {
-    VLOG(1) << "Updating configs:";
+    QUIC_LOG(INFO) << "Updating configs:";
 
     QuicWriterMutexLock locked(&configs_lock_);
     ConfigMap new_configs;
 
     for (std::vector<QuicReferenceCountedPointer<Config>>::const_iterator i =
              parsed_configs.begin();
          i != parsed_configs.end(); ++i) {
       QuicReferenceCountedPointer<Config> config = *i;
 
       ConfigMap::iterator it = configs_.find(config->id);
       if (it != configs_.end()) {
-        VLOG(1) << "Keeping scid: " << QuicTextUtils::HexEncode(config->id)
-                << " orbit: "
-                << QuicTextUtils::HexEncode(
-                       reinterpret_cast<const char*>(config->orbit), kOrbitSize)
-                << " new primary_time " << config->primary_time.ToUNIXSeconds()
-                << " old primary_time "
-                << it->second->primary_time.ToUNIXSeconds() << " new priority "
-                << config->priority << " old priority " << it->second->priority;
+        QUIC_LOG(INFO) << "Keeping scid: "
+                       << QuicTextUtils::HexEncode(config->id) << " orbit: "
+                       << QuicTextUtils::HexEncode(
+                              reinterpret_cast<const char*>(config->orbit),
+                              kOrbitSize)
+                       << " new primary_time "
+                       << config->primary_time.ToUNIXSeconds()
+                       << " old primary_time "
+                       << it->second->primary_time.ToUNIXSeconds()
+                       << " new priority " << config->priority
+                       << " old priority " << it->second->priority;
         // Update primary_time and priority.
         it->second->primary_time = config->primary_time;
         it->second->priority = config->priority;
         new_configs.insert(*it);
       } else {
-        VLOG(1) << "Adding scid: " << QuicTextUtils::HexEncode(config->id)
-                << " orbit: "
-                << QuicTextUtils::HexEncode(
-                       reinterpret_cast<const char*>(config->orbit), kOrbitSize)
-                << " primary_time " << config->primary_time.ToUNIXSeconds()
-                << " priority " << config->priority;
+        QUIC_LOG(INFO) << "Adding scid: "
+                       << QuicTextUtils::HexEncode(config->id) << " orbit: "
+                       << QuicTextUtils::HexEncode(
+                              reinterpret_cast<const char*>(config->orbit),
+                              kOrbitSize)
+                       << " primary_time "
+                       << config->primary_time.ToUNIXSeconds() << " priority "
+                       << config->priority;
         new_configs.insert(std::make_pair(config->id, config));
       }
     }
 
     configs_.swap(new_configs);
     SelectNewPrimaryConfig(now);
     DCHECK(primary_config_.get());
     DCHECK_EQ(configs_.find(primary_config_->id)->second.get(),
               primary_config_.get());
   }
@@ skipping 685 matching lines @@
       }
     } else {
       next_config_promotion_time_ = config->primary_time;
     }
 
     if (primary_config_) {
       primary_config_->is_primary = false;
     }
     primary_config_ = new_primary;
     new_primary->is_primary = true;
-    DVLOG(1) << "New primary config.  orbit: "
-             << QuicTextUtils::HexEncode(
-                    reinterpret_cast<const char*>(primary_config_->orbit),
-                    kOrbitSize);
+    QUIC_DLOG(INFO) << "New primary config.  orbit: "
+                    << QuicTextUtils::HexEncode(reinterpret_cast<const char*>(
+                                                    primary_config_->orbit),
+                                                kOrbitSize);
     if (primary_config_changed_cb_.get() != nullptr) {
       primary_config_changed_cb_->Run(primary_config_->id);
     }
 
     return;
   }
 
   // All config's primary times are in the past. We should make the most recent
   // and highest priority candidate primary.
   QuicReferenceCountedPointer<Config> new_primary = best_candidate;
   if (primary_config_) {
     primary_config_->is_primary = false;
   }
   primary_config_ = new_primary;
   new_primary->is_primary = true;
-  DVLOG(1) << "New primary config.  orbit: "
-           << QuicTextUtils::HexEncode(
-                  reinterpret_cast<const char*>(primary_config_->orbit),
-                  kOrbitSize)
-           << " scid: " << QuicTextUtils::HexEncode(primary_config_->id);
+  QUIC_DLOG(INFO) << "New primary config.  orbit: "
+                  << QuicTextUtils::HexEncode(
+                         reinterpret_cast<const char*>(primary_config_->orbit),
+                         kOrbitSize)
+                  << " scid: " << QuicTextUtils::HexEncode(primary_config_->id);
   next_config_promotion_time_ = QuicWallTime::Zero();
   if (primary_config_changed_cb_.get() != nullptr) {
     primary_config_changed_cb_->Run(primary_config_->id);
   }
 }
 
 class QuicCryptoServerConfig::EvaluateClientHelloCallback
     : public ProofSource::Callback {
  public:
   EvaluateClientHelloCallback(
@@ skipping 195 matching lines @@
 
   if (signed_config->chain != nullptr &&
       !ValidateExpectedLeafCertificate(client_hello,
                                        signed_config->chain->certs)) {
     info->reject_reasons.push_back(INVALID_EXPECTED_LEAF_CERTIFICATE);
   }
 
   if (info->client_nonce.size() != kNonceSize) {
     info->reject_reasons.push_back(CLIENT_NONCE_INVALID_FAILURE);
     // Invalid client nonce.
-    LOG(ERROR) << "Invalid client nonce: " << client_hello.DebugString();
-    DVLOG(1) << "Invalid client nonce.";
+    QUIC_LOG_FIRST_N(ERROR, 2) << "Invalid client nonce: "
+                               << client_hello.DebugString();
+    QUIC_DLOG(INFO) << "Invalid client nonce.";
   }
 
   // Server nonce is optional, and used for key derivation if present.
   client_hello.GetStringPiece(kServerNonceTag, &info->server_nonce);
 
-  DVLOG(1) << "No 0-RTT replay protection in QUIC_VERSION_33 and higher.";
+  QUIC_DVLOG(1) << "No 0-RTT replay protection in QUIC_VERSION_33 and higher.";
   // If the server nonce is empty and we're requiring handshake confirmation
   // for DoS reasons then we must reject the CHLO.
   if (FLAGS_quic_reloadable_flag_quic_require_handshake_confirmation &&
       info->server_nonce.empty()) {
     info->reject_reasons.push_back(SERVER_NONCE_REQUIRED_FAILURE);
   }
   helper.ValidationComplete(QUIC_NO_ERROR, "", std::move(proof_source_details));
 }
 
 bool QuicCryptoServerConfig::BuildServerConfigUpdateMessage(
@@ skipping 26 matching lines @@
   out->set_tag(kSCUP);
   out->SetStringPiece(kSCFG, serialized);
   out->SetStringPiece(kSourceAddressTokenTag, source_address_token);
   out->SetValue(kSTTL,
                 expiry_time.AbsoluteDifference(clock->WallNow()).ToSeconds());
 
   QuicReferenceCountedPointer<ProofSource::Chain> chain;
   QuicCryptoProof proof;
   if (!proof_source_->GetProof(server_address, params.sni, serialized, version,
                                chlo_hash, connection_options, &chain, &proof)) {
-    DVLOG(1) << "Server: failed to get proof.";
+    QUIC_DVLOG(1) << "Server: failed to get proof.";
     return false;
   }
 
   const string compressed = CompressChain(
       compressed_certs_cache, chain, params.client_common_set_hashes,
       params.client_cached_cert_hashes, common_cert_sets);
 
   out->SetStringPiece(kCertificateTag, compressed);
   out->SetStringPiece(kPROF, proof.signature);
   if (params.sct_supported_by_client && enable_serving_sct_) {
     if (proof.leaf_cert_scts.empty()) {
-      DLOG(WARNING) << "SCT is expected but it is empty. sni: " << params.sni
-                    << " server_address: " << server_address.ToString();
+      QUIC_LOG_EVERY_N_SEC(WARNING, 60)
+          << "SCT is expected but it is empty.  sni: " << params.sni
+          << " server_address: " << server_address.ToString();
     } else {
       out->SetStringPiece(kCertificateSCTTag, proof.leaf_cert_scts);
     }
   }
   return true;
 }
 
 void QuicCryptoServerConfig::BuildServerConfigUpdateMessage(
     QuicVersion version,
     StringPiece chlo_hash,
@@ skipping 95 matching lines @@
   }
 
   const string compressed =
       CompressChain(compressed_certs_cache, chain, client_common_set_hashes,
                     client_cached_cert_hashes, common_cert_sets);
 
   message.SetStringPiece(kCertificateTag, compressed);
   message.SetStringPiece(kPROF, signature);
   if (sct_supported_by_client && enable_serving_sct_) {
     if (leaf_cert_sct.empty()) {
-      DLOG(WARNING) << "SCT is expected but it is empty.";
+      QUIC_LOG_EVERY_N_SEC(WARNING, 60) << "SCT is expected but it is empty.";
     } else {
       message.SetStringPiece(kCertificateSCTTag, leaf_cert_sct);
     }
   }
 
   cb->Run(true, message);
 }
 
 void QuicCryptoServerConfig::BuildRejection(
     QuicVersion version,
     QuicWallTime now,
     const Config& config,
     const CryptoHandshakeMessage& client_hello,
     const ClientHelloInfo& info,
     const CachedNetworkParameters& cached_network_params,
     bool use_stateless_rejects,
     QuicConnectionId server_designated_connection_id,
     QuicRandom* rand,
     QuicCompressedCertsCache* compressed_certs_cache,
     QuicReferenceCountedPointer<QuicCryptoNegotiatedParameters> params,
     const QuicSignedServerConfig& signed_config,
     QuicByteCount total_framing_overhead,
     QuicByteCount chlo_packet_size,
     CryptoHandshakeMessage* out) const {
   if (FLAGS_quic_reloadable_flag_enable_quic_stateless_reject_support &&
       use_stateless_rejects) {
-    DVLOG(1) << "QUIC Crypto server config returning stateless reject "
-             << "with server-designated connection ID "
-             << server_designated_connection_id;
+    QUIC_DVLOG(1) << "QUIC Crypto server config returning stateless reject "
+                  << "with server-designated connection ID "
+                  << server_designated_connection_id;
     out->set_tag(kSREJ);
     out->SetValue(kRCID, server_designated_connection_id);
   } else {
     out->set_tag(kREJ);
   }
   out->SetStringPiece(kSCFG, config.serialized);
   out->SetStringPiece(
       kSourceAddressTokenTag,
       NewSourceAddressToken(config, info.source_address_tokens, info.client_ip,
                             rand, info.now, &cached_network_params));
@@ skipping 48 matching lines @@
       params->sct_supported_by_client && enable_serving_sct_;
   const string& cert_sct = signed_config.proof.leaf_cert_scts;
   const size_t sct_size = should_return_sct ? cert_sct.size() : 0;
   const size_t total_size =
       signed_config.proof.signature.size() + compressed.size() + sct_size;
   if (info.valid_source_address_token || total_size < max_unverified_size) {
     out->SetStringPiece(kCertificateTag, compressed);
     out->SetStringPiece(kPROF, signed_config.proof.signature);
     if (should_return_sct) {
       if (cert_sct.empty()) {
-        DLOG(WARNING) << "SCT is expected but it is empty.";
+        QUIC_LOG_EVERY_N_SEC(WARNING, 60) << "SCT is expected but it is empty.";
       } else {
         out->SetStringPiece(kCertificateSCTTag, cert_sct);
       }
     }
   } else {
-    DLOG(WARNING) << "Sending inchoate REJ for hostname: " << info.sni
-                  << " signature: " << signed_config.proof.signature.size()
-                  << " cert: " << compressed.size() << " sct:" << sct_size
-                  << " total: " << total_size
-                  << " max: " << max_unverified_size;
+    QUIC_LOG_EVERY_N_SEC(WARNING, 60)
+        << "Sending inchoate REJ for hostname: " << info.sni
+        << " signature: " << signed_config.proof.signature.size()
+        << " cert: " << compressed.size() << " sct:" << sct_size
+        << " total: " << total_size << " max: " << max_unverified_size;
   }
 }
 
 string QuicCryptoServerConfig::CompressChain(
     QuicCompressedCertsCache* compressed_certs_cache,
     const QuicReferenceCountedPointer<ProofSource::Chain>& chain,
     const string& client_common_set_hashes,
     const string& client_cached_cert_hashes,
     const CommonCertSets* common_sets) {
   // Check whether the compressed certs is available in the cache.
@@ skipping 14 matching lines @@
   return compressed;
 }
 
 QuicReferenceCountedPointer<QuicCryptoServerConfig::Config>
 QuicCryptoServerConfig::ParseConfigProtobuf(
     const std::unique_ptr<QuicServerConfigProtobuf>& protobuf) {
   std::unique_ptr<CryptoHandshakeMessage> msg(
       CryptoFramer::ParseMessage(protobuf->config()));
 
   if (msg->tag() != kSCFG) {
-    LOG(WARNING) << "Server config message has tag " << msg->tag()
-                 << " expected " << kSCFG;
+    QUIC_LOG(WARNING) << "Server config message has tag " << msg->tag()
+                      << " expected " << kSCFG;
     return nullptr;
   }
 
   QuicReferenceCountedPointer<Config> config(new Config);
   config->serialized = protobuf->config();
   config->source_address_token_boxer = &source_address_token_boxer_;
 
   if (protobuf->has_primary_time()) {
     config->primary_time =
         QuicWallTime::FromUNIXSeconds(protobuf->primary_time());
   }
 
   config->priority = protobuf->priority();
 
   StringPiece scid;
   if (!msg->GetStringPiece(kSCID, &scid)) {
-    LOG(WARNING) << "Server config message is missing SCID";
+    QUIC_LOG(WARNING) << "Server config message is missing SCID";
     return nullptr;
   }
   config->id = scid.as_string();
 
   const QuicTag* aead_tags;
   size_t aead_len;
   if (msg->GetTaglist(kAEAD, &aead_tags, &aead_len) != QUIC_NO_ERROR) {
-    LOG(WARNING) << "Server config message is missing AEAD";
+    QUIC_LOG(WARNING) << "Server config message is missing AEAD";
     return nullptr;
   }
   config->aead = std::vector<QuicTag>(aead_tags, aead_tags + aead_len);
 
   const QuicTag* kexs_tags;
   size_t kexs_len;
   if (msg->GetTaglist(kKEXS, &kexs_tags, &kexs_len) != QUIC_NO_ERROR) {
-    LOG(WARNING) << "Server config message is missing KEXS";
+    QUIC_LOG(WARNING) << "Server config message is missing KEXS";
     return nullptr;
   }
 
   const QuicTag* tbkp_tags;
   size_t tbkp_len;
   QuicErrorCode err;
   if ((err = msg->GetTaglist(kTBKP, &tbkp_tags, &tbkp_len)) !=
           QUIC_CRYPTO_MESSAGE_PARAMETER_NOT_FOUND &&
       err != QUIC_NO_ERROR) {
-    LOG(WARNING) << "Server config message is missing or has invalid TBKP";
+    QUIC_LOG(WARNING) << "Server config message is missing or has invalid TBKP";
     return nullptr;
   }
   config->tb_key_params = std::vector<QuicTag>(tbkp_tags, tbkp_tags + tbkp_len);
 
   StringPiece orbit;
   if (!msg->GetStringPiece(kORBT, &orbit)) {
-    LOG(WARNING) << "Server config message is missing ORBT";
+    QUIC_LOG(WARNING) << "Server config message is missing ORBT";
     return nullptr;
   }
 
   if (orbit.size() != kOrbitSize) {
-    LOG(WARNING) << "Orbit value in server config is the wrong length."
-                    " Got "
-                 << orbit.size() << " want " << kOrbitSize;
+    QUIC_LOG(WARNING) << "Orbit value in server config is the wrong length."
+                         " Got "
+                      << orbit.size() << " want " << kOrbitSize;
     return nullptr;
   }
   static_assert(sizeof(config->orbit) == kOrbitSize, "incorrect orbit size");
   memcpy(config->orbit, orbit.data(), sizeof(config->orbit));
 
   if (kexs_len != protobuf->key_size()) {
-    LOG(WARNING) << "Server config has " << kexs_len
-                 << " key exchange methods configured, but "
-                 << protobuf->key_size() << " private keys";
+    QUIC_LOG(WARNING) << "Server config has " << kexs_len
+                      << " key exchange methods configured, but "
+                      << protobuf->key_size() << " private keys";
     return nullptr;
   }
 
   const QuicTag* proof_demand_tags;
   size_t num_proof_demand_tags;
   if (msg->GetTaglist(kPDMD, &proof_demand_tags, &num_proof_demand_tags) ==
       QUIC_NO_ERROR) {
     for (size_t i = 0; i < num_proof_demand_tags; i++) {
       if (proof_demand_tags[i] == kCHID) {
         config->channel_id_enabled = true;
@@ skipping 10 matching lines @@
 
     for (size_t j = 0; j < protobuf->key_size(); j++) {
       const QuicServerConfigProtobuf::PrivateKey& key = protobuf->key(i);
       if (key.tag() == tag) {
         private_key = key.private_key();
         break;
       }
     }
 
     if (private_key.empty()) {
-      LOG(WARNING) << "Server config contains key exchange method without "
-                      "corresponding private key: "
-                   << tag;
+      QUIC_LOG(WARNING) << "Server config contains key exchange method without "
+                           "corresponding private key: "
+                        << tag;
       return nullptr;
     }
 
     std::unique_ptr<KeyExchange> ka;
     switch (tag) {
       case kC255:
         ka.reset(Curve25519KeyExchange::New(private_key));
         if (!ka.get()) {
-          LOG(WARNING) << "Server config contained an invalid curve25519"
-                          " private key.";
+          QUIC_LOG(WARNING) << "Server config contained an invalid curve25519"
+                               " private key.";
           return nullptr;
         }
         break;
       case kP256:
         ka.reset(P256KeyExchange::New(private_key));
         if (!ka.get()) {
-          LOG(WARNING) << "Server config contained an invalid P-256"
-                          " private key.";
+          QUIC_LOG(WARNING) << "Server config contained an invalid P-256"
+                               " private key.";
           return nullptr;
         }
         break;
       default:
-        LOG(WARNING) << "Server config message contains unknown key exchange "
-                        "method: "
-                     << tag;
+        QUIC_LOG(WARNING)
+            << "Server config message contains unknown key exchange "
+               "method: "
+            << tag;
         return nullptr;
     }
 
     for (const auto& key_exchange : config->key_exchanges) {
       if (key_exchange->tag() == tag) {
-        LOG(WARNING) << "Duplicate key exchange in config: " << tag;
+        QUIC_LOG(WARNING) << "Duplicate key exchange in config: " << tag;
         return nullptr;
       }
     }
 
     config->key_exchanges.push_back(std::move(ka));
   }
 
   uint64_t expiry_seconds;
   if (msg->GetUint64(kEXPY, &expiry_seconds) != QUIC_NO_ERROR) {
-    LOG(WARNING) << "Server config message is missing EXPY";
+    QUIC_LOG(WARNING) << "Server config message is missing EXPY";
     return nullptr;
   }
   config->expiry_time = QuicWallTime::FromUNIXSeconds(expiry_seconds);
 
   return config;
 }
 
 void QuicCryptoServerConfig::SetEphemeralKeySource(
     EphemeralKeySource* ephemeral_key_source) {
   ephemeral_key_source_.reset(ephemeral_key_source);
@@ skipping 209 matching lines @@
       expiry_time(QuicWallTime::Zero()),
       priority(0),
       source_address_token_boxer(nullptr) {}
 
 QuicCryptoServerConfig::Config::~Config() {}
 
 QuicSignedServerConfig::QuicSignedServerConfig() {}
 QuicSignedServerConfig::~QuicSignedServerConfig() {}
 
 }  // namespace net