net/quic/quic_connection_logger.cc

   1 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "net/quic/quic_connection_logger.h"
   6
   7 #include <algorithm>
   8 #include <string>
   9
  10 #include "base/bind.h"
  11 #include "base/callback.h"
  12 #include "base/metrics/histogram.h"
  13 #include "base/metrics/sparse_histogram.h"
  14 #include "base/profiler/scoped_tracker.h"
  15 #include "base/strings/string_number_conversions.h"
  16 #include "base/values.h"
  17 #include "net/base/net_util.h"
  18 #include "net/cert/cert_verify_result.h"
  19 #include "net/cert/x509_certificate.h"
  20 #include "net/log/net_log.h"
  21 #include "net/quic/crypto/crypto_handshake_message.h"
  22 #include "net/quic/crypto/crypto_protocol.h"
  23 #include "net/quic/quic_address_mismatch.h"
  24 #include "net/quic/quic_socket_address_coder.h"
  25
  26 using base::StringPiece;
  27 using std::string;
  28
  29 namespace net {
  30
  31 namespace {
  32
  33 // We have ranges-of-buckets in the cumulative histogram (covering 21 packet
  34 // sequences) of length 2, 3, 4, ... 22.
  35 // Hence the largest sample is bounded by the sum of those numbers.
  36 const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2;
  37
  38 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
  39                                       const IPEndPoint* peer_address,
  40                                       size_t packet_size,
  41                                       NetLog::LogLevel /* log_level */) {
  42   base::DictionaryValue* dict = new base::DictionaryValue();
  43   dict->SetString("self_address", self_address->ToString());
  44   dict->SetString("peer_address", peer_address->ToString());
  45   dict->SetInteger("size", packet_size);
  46   return dict;
  47 }
  48
  49 base::Value* NetLogQuicPacketSentCallback(
  50     const SerializedPacket& serialized_packet,
  51     EncryptionLevel level,
  52     TransmissionType transmission_type,
  53     size_t packet_size,
  54     QuicTime sent_time,
  55     NetLog::LogLevel /* log_level */) {
  56   base::DictionaryValue* dict = new base::DictionaryValue();
  57   dict->SetInteger("encryption_level", level);
  58   dict->SetInteger("transmission_type", transmission_type);
  59   dict->SetString("packet_sequence_number",
  60                   base::Uint64ToString(serialized_packet.sequence_number));
  61   dict->SetInteger("size", packet_size);
  62   dict->SetInteger("sent_time_us",
  63                    static_cast<int>(sent_time.ToDebuggingValue()));
  64   return dict;
  65 }
  66
  67 base::Value* NetLogQuicPacketRetransmittedCallback(
  68     QuicPacketSequenceNumber old_sequence_number,
  69     QuicPacketSequenceNumber new_sequence_number,
  70     NetLog::LogLevel /* log_level */) {
  71   base::DictionaryValue* dict = new base::DictionaryValue();
  72   dict->SetString("old_packet_sequence_number",
  73                   base::Uint64ToString(old_sequence_number));
  74   dict->SetString("new_packet_sequence_number",
  75                   base::Uint64ToString(new_sequence_number));
  76   return dict;
  77 }
  78
  79 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
  80                                             NetLog::LogLevel /* log_level */) {
  81   base::DictionaryValue* dict = new base::DictionaryValue();
  82   dict->SetString("connection_id",
  83                   base::Uint64ToString(header->public_header.connection_id));
  84   dict->SetInteger("reset_flag", header->public_header.reset_flag);
  85   dict->SetInteger("version_flag", header->public_header.version_flag);
  86   dict->SetString("packet_sequence_number",
  87                   base::Uint64ToString(header->packet_sequence_number));
  88   dict->SetInteger("entropy_flag", header->entropy_flag);
  89   dict->SetInteger("fec_flag", header->fec_flag);
  90   dict->SetInteger("fec_group", static_cast<int>(header->fec_group));
  91   return dict;
  92 }
  93
  94 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
  95                                            NetLog::LogLevel /* log_level */) {
  96   base::DictionaryValue* dict = new base::DictionaryValue();
  97   dict->SetInteger("stream_id", frame->stream_id);
  98   dict->SetBoolean("fin", frame->fin);
  99   dict->SetString("offset", base::Uint64ToString(frame->offset));
 100   dict->SetInteger("length", frame->data.TotalBufferSize());
 101   return dict;
 102 }
 103
 104 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
 105                                         NetLog::LogLevel /* log_level */) {
 106   base::DictionaryValue* dict = new base::DictionaryValue();
 107   dict->SetString("largest_observed",
 108                   base::Uint64ToString(frame->largest_observed));
 109   dict->SetInteger(
 110       "delta_time_largest_observed_us",
 111       static_cast<int>(frame->delta_time_largest_observed.ToMicroseconds()));
 112   dict->SetInteger("entropy_hash",
 113                    frame->entropy_hash);
 114   dict->SetBoolean("truncated", frame->is_truncated);
 115
 116   base::ListValue* missing = new base::ListValue();
 117   dict->Set("missing_packets", missing);
 118   const SequenceNumberSet& missing_packets = frame->missing_packets;
 119   for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 120        it != missing_packets.end(); ++it) {
 121     missing->AppendString(base::Uint64ToString(*it));
 122   }
 123
 124   base::ListValue* revived = new base::ListValue();
 125   dict->Set("revived_packets", revived);
 126   const SequenceNumberSet& revived_packets = frame->revived_packets;
 127   for (SequenceNumberSet::const_iterator it = revived_packets.begin();
 128        it != revived_packets.end(); ++it) {
 129     revived->AppendString(base::Uint64ToString(*it));
 130   }
 131
 132   base::ListValue* received = new base::ListValue();
 133   dict->Set("received_packet_times", received);
 134   const PacketTimeList& received_times = frame->received_packet_times;
 135   for (PacketTimeList::const_iterator it = received_times.begin();
 136        it != received_times.end(); ++it) {
 137     base::DictionaryValue* info = new base::DictionaryValue();
 138     info->SetInteger("sequence_number", static_cast<int>(it->first));
 139     info->SetInteger("received",
 140                      static_cast<int>(it->second.ToDebuggingValue()));
 141     received->Append(info);
 142   }
 143
 144   return dict;
 145 }
 146
 147 base::Value* NetLogQuicRstStreamFrameCallback(
 148     const QuicRstStreamFrame* frame,
 149     NetLog::LogLevel /* log_level */) {
 150   base::DictionaryValue* dict = new base::DictionaryValue();
 151   dict->SetInteger("stream_id", frame->stream_id);
 152   dict->SetInteger("quic_rst_stream_error", frame->error_code);
 153   dict->SetString("details", frame->error_details);
 154   return dict;
 155 }
 156
 157 base::Value* NetLogQuicConnectionCloseFrameCallback(
 158     const QuicConnectionCloseFrame* frame,
 159     NetLog::LogLevel /* log_level */) {
 160   base::DictionaryValue* dict = new base::DictionaryValue();
 161   dict->SetInteger("quic_error", frame->error_code);
 162   dict->SetString("details", frame->error_details);
 163   return dict;
 164 }
 165
 166 base::Value* NetLogQuicWindowUpdateFrameCallback(
 167     const QuicWindowUpdateFrame* frame,
 168     NetLog::LogLevel /* log_level */) {
 169   base::DictionaryValue* dict = new base::DictionaryValue();
 170   dict->SetInteger("stream_id", frame->stream_id);
 171   dict->SetString("byte_offset", base::Uint64ToString(frame->byte_offset));
 172   return dict;
 173 }
 174
 175 base::Value* NetLogQuicBlockedFrameCallback(
 176     const QuicBlockedFrame* frame,
 177     NetLog::LogLevel /* log_level */) {
 178   base::DictionaryValue* dict = new base::DictionaryValue();
 179   dict->SetInteger("stream_id", frame->stream_id);
 180   return dict;
 181 }
 182
 183 base::Value* NetLogQuicGoAwayFrameCallback(
 184     const QuicGoAwayFrame* frame,
 185     NetLog::LogLevel /* log_level */) {
 186   base::DictionaryValue* dict = new base::DictionaryValue();
 187   dict->SetInteger("quic_error", frame->error_code);
 188   dict->SetInteger("last_good_stream_id", frame->last_good_stream_id);
 189   dict->SetString("reason_phrase", frame->reason_phrase);
 190   return dict;
 191 }
 192
 193 base::Value* NetLogQuicStopWaitingFrameCallback(
 194     const QuicStopWaitingFrame* frame,
 195     NetLog::LogLevel /* log_level */) {
 196   base::DictionaryValue* dict = new base::DictionaryValue();
 197   base::DictionaryValue* sent_info = new base::DictionaryValue();
 198   dict->Set("sent_info", sent_info);
 199   sent_info->SetString("least_unacked",
 200                        base::Uint64ToString(frame->least_unacked));
 201   return dict;
 202 }
 203
 204 base::Value* NetLogQuicVersionNegotiationPacketCallback(
 205     const QuicVersionNegotiationPacket* packet,
 206     NetLog::LogLevel /* log_level */) {
 207   base::DictionaryValue* dict = new base::DictionaryValue();
 208   base::ListValue* versions = new base::ListValue();
 209   dict->Set("versions", versions);
 210   for (QuicVersionVector::const_iterator it = packet->versions.begin();
 211        it != packet->versions.end(); ++it) {
 212     versions->AppendString(QuicVersionToString(*it));
 213   }
 214   return dict;
 215 }
 216
 217 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
 218     const CryptoHandshakeMessage* message,
 219     NetLog::LogLevel /* log_level */) {
 220   base::DictionaryValue* dict = new base::DictionaryValue();
 221   dict->SetString("quic_crypto_handshake_message", message->DebugString());
 222   return dict;
 223 }
 224
 225 base::Value* NetLogQuicOnConnectionClosedCallback(
 226     QuicErrorCode error,
 227     bool from_peer,
 228     NetLog::LogLevel /* log_level */) {
 229   base::DictionaryValue* dict = new base::DictionaryValue();
 230   dict->SetInteger("quic_error", error);
 231   dict->SetBoolean("from_peer", from_peer);
 232   return dict;
 233 }
 234
 235 base::Value* NetLogQuicCertificateVerifiedCallback(
 236     scoped_refptr<X509Certificate> cert,
 237     NetLog::LogLevel /* log_level */) {
 238   // Only the subjects are logged so that we can investigate connection pooling.
 239   // More fields could be logged in the future.
 240   std::vector<std::string> dns_names;
 241   cert->GetDNSNames(&dns_names);
 242   base::DictionaryValue* dict = new base::DictionaryValue();
 243   base::ListValue* subjects = new base::ListValue();
 244   for (std::vector<std::string>::const_iterator it = dns_names.begin();
 245        it != dns_names.end(); it++) {
 246     subjects->Append(new base::StringValue(*it));
 247   }
 248   dict->Set("subjects", subjects);
 249   return dict;
 250 }
 251
 252 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
 253   UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
 254                        num_consecutive_missing_packets);
 255 }
 256
 257 void UpdatePublicResetAddressMismatchHistogram(
 258     const IPEndPoint& server_hello_address,
 259     const IPEndPoint& public_reset_address) {
 260   int sample = GetAddressMismatch(server_hello_address, public_reset_address);
 261   // We are seemingly talking to an older server that does not support the
 262   // feature, so we can't report the results in the histogram.
 263   if (sample < 0) {
 264     return;
 265   }
 266   UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch2",
 267                             sample, QUIC_ADDRESS_MISMATCH_MAX);
 268 }
 269
 270 // If |address| is an IPv4-mapped IPv6 address, returns ADDRESS_FAMILY_IPV4
 271 // instead of ADDRESS_FAMILY_IPV6. Othewise, behaves like GetAddressFamily().
 272 AddressFamily GetRealAddressFamily(const IPAddressNumber& address) {
 273   return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 :
 274       GetAddressFamily(address);
 275 }
 276
 277 }  // namespace
 278
 279 QuicConnectionLogger::QuicConnectionLogger(
 280     QuicSession* session,
 281     const char* const connection_description,
 282     const BoundNetLog& net_log)
 283     : net_log_(net_log),
 284       session_(session),
 285       last_received_packet_sequence_number_(0),
 286       last_received_packet_size_(0),
 287       previous_received_packet_size_(0),
 288       largest_received_packet_sequence_number_(0),
 289       largest_received_missing_packet_sequence_number_(0),
 290       num_out_of_order_received_packets_(0),
 291       num_out_of_order_large_received_packets_(0),
 292       num_packets_received_(0),
 293       num_truncated_acks_sent_(0),
 294       num_truncated_acks_received_(0),
 295       num_frames_received_(0),
 296       num_duplicate_frames_received_(0),
 297       num_incorrect_connection_ids_(0),
 298       num_undecryptable_packets_(0),
 299       num_duplicate_packets_(0),
 300       num_blocked_frames_received_(0),
 301       num_blocked_frames_sent_(0),
 302       connection_description_(connection_description) {
 303 }
 304
 305 QuicConnectionLogger::~QuicConnectionLogger() {
 306   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
 307                        num_out_of_order_received_packets_);
 308   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderLargePacketsReceived",
 309                        num_out_of_order_large_received_packets_);
 310   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
 311                        num_truncated_acks_sent_);
 312   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
 313                        num_truncated_acks_received_);
 314   UMA_HISTOGRAM_COUNTS("Net.QuicSession.IncorrectConnectionIDsReceived",
 315                        num_incorrect_connection_ids_);
 316   UMA_HISTOGRAM_COUNTS("Net.QuicSession.UndecryptablePacketsReceived",
 317                        num_undecryptable_packets_);
 318   UMA_HISTOGRAM_COUNTS("Net.QuicSession.DuplicatePacketsReceived",
 319                        num_duplicate_packets_);
 320   UMA_HISTOGRAM_COUNTS("Net.QuicSession.BlockedFrames.Received",
 321                        num_blocked_frames_received_);
 322   UMA_HISTOGRAM_COUNTS("Net.QuicSession.BlockedFrames.Sent",
 323                        num_blocked_frames_sent_);
 324   UMA_HISTOGRAM_COUNTS("Net.QuicSession.HeadersStream.EarlyFramesReceived",
 325                        session_->headers_stream()->num_early_frames_received());
 326
 327   if (num_frames_received_ > 0) {
 328     int duplicate_stream_frame_per_thousand =
 329         num_duplicate_frames_received_ * 1000 / num_frames_received_;
 330     if (num_packets_received_ < 100) {
 331       UMA_HISTOGRAM_CUSTOM_COUNTS(
 332           "Net.QuicSession.StreamFrameDuplicatedShortConnection",
 333           duplicate_stream_frame_per_thousand, 1, 1000, 75);
 334     } else {
 335       UMA_HISTOGRAM_CUSTOM_COUNTS(
 336           "Net.QuicSession.StreamFrameDuplicatedLongConnection",
 337           duplicate_stream_frame_per_thousand, 1, 1000, 75);
 338
 339     }
 340   }
 341
 342   RecordLossHistograms();
 343 }
 344
 345 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
 346   switch (frame.type) {
 347     case PADDING_FRAME:
 348       break;
 349     case STREAM_FRAME:
 350       net_log_.AddEvent(
 351           NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
 352           base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
 353       break;
 354     case ACK_FRAME: {
 355       net_log_.AddEvent(
 356           NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
 357           base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
 358       const SequenceNumberSet& missing_packets =
 359           frame.ack_frame->missing_packets;
 360       const uint8 max_ranges = std::numeric_limits<uint8>::max();
 361       // Compute an upper bound on the number of NACK ranges. If the bound
 362       // is below the max, then it clearly isn't truncated.
 363       if (missing_packets.size() < max_ranges ||
 364           (*missing_packets.rbegin() - *missing_packets.begin() -
 365            missing_packets.size() + 1) < max_ranges) {
 366         break;
 367       }
 368       size_t num_ranges = 0;
 369       QuicPacketSequenceNumber last_missing = 0;
 370       for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 371            it != missing_packets.end(); ++it) {
 372         if (*it != last_missing + 1 && ++num_ranges >= max_ranges) {
 373           ++num_truncated_acks_sent_;
 374           break;
 375         }
 376         last_missing = *it;
 377       }
 378       break;
 379     }
 380     case RST_STREAM_FRAME:
 381       UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
 382                                   frame.rst_stream_frame->error_code);
 383       net_log_.AddEvent(
 384           NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
 385           base::Bind(&NetLogQuicRstStreamFrameCallback,
 386                      frame.rst_stream_frame));
 387       break;
 388     case CONNECTION_CLOSE_FRAME:
 389       net_log_.AddEvent(
 390           NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
 391           base::Bind(&NetLogQuicConnectionCloseFrameCallback,
 392                      frame.connection_close_frame));
 393       break;
 394     case GOAWAY_FRAME:
 395       net_log_.AddEvent(
 396           NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_SENT,
 397           base::Bind(&NetLogQuicGoAwayFrameCallback,
 398                      frame.goaway_frame));
 399       break;
 400     case WINDOW_UPDATE_FRAME:
 401       net_log_.AddEvent(
 402           NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT,
 403           base::Bind(&NetLogQuicWindowUpdateFrameCallback,
 404                      frame.window_update_frame));
 405       break;
 406     case BLOCKED_FRAME:
 407       ++num_blocked_frames_sent_;
 408       net_log_.AddEvent(
 409           NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT,
 410           base::Bind(&NetLogQuicBlockedFrameCallback,
 411                      frame.blocked_frame));
 412       break;
 413     case STOP_WAITING_FRAME:
 414       net_log_.AddEvent(
 415           NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT,
 416           base::Bind(&NetLogQuicStopWaitingFrameCallback,
 417                      frame.stop_waiting_frame));
 418       break;
 419     case PING_FRAME:
 420       UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.ConnectionFlowControlBlocked",
 421                             session_->IsConnectionFlowControlBlocked());
 422       UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.StreamFlowControlBlocked",
 423                             session_->IsStreamFlowControlBlocked());
 424       // PingFrame has no contents to log, so just record that it was sent.
 425       net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_SENT);
 426       break;
 427     default:
 428       DCHECK(false) << "Illegal frame type: " << frame.type;
 429   }
 430 }
 431
 432 void QuicConnectionLogger::OnPacketSent(
 433     const SerializedPacket& serialized_packet,
 434     QuicPacketSequenceNumber original_sequence_number,
 435     EncryptionLevel level,
 436     TransmissionType transmission_type,
 437     const QuicEncryptedPacket& packet,
 438     QuicTime sent_time) {
 439   if (original_sequence_number == 0) {
 440     net_log_.AddEvent(
 441         NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 442         base::Bind(&NetLogQuicPacketSentCallback, serialized_packet,
 443                    level, transmission_type, packet.length(), sent_time));
 444   }  else {
 445     net_log_.AddEvent(
 446         NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 447         base::Bind(&NetLogQuicPacketRetransmittedCallback,
 448                    original_sequence_number,
 449                    serialized_packet.sequence_number));
 450   }
 451 }
 452
 453 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 454                                             const IPEndPoint& peer_address,
 455                                             const QuicEncryptedPacket& packet) {
 456   if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) {
 457     local_address_from_self_ = self_address;
 458     UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromSelf",
 459                               GetRealAddressFamily(self_address.address()),
 460                               ADDRESS_FAMILY_LAST);
 461   }
 462
 463   previous_received_packet_size_ = last_received_packet_size_;
 464   last_received_packet_size_ = packet.length();
 465   net_log_.AddEvent(
 466       NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
 467       base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
 468                  packet.length()));
 469 }
 470
 471 void QuicConnectionLogger::OnIncorrectConnectionId(
 472     QuicConnectionId connection_id) {
 473   ++num_incorrect_connection_ids_;
 474 }
 475
 476 void QuicConnectionLogger::OnUndecryptablePacket() {
 477   ++num_undecryptable_packets_;
 478 }
 479
 480 void QuicConnectionLogger::OnDuplicatePacket(
 481     QuicPacketSequenceNumber sequence_number) {
 482   ++num_duplicate_packets_;
 483 }
 484
 485 void QuicConnectionLogger::OnProtocolVersionMismatch(
 486     QuicVersion received_version) {
 487   // TODO(rtenneti): Add logging.
 488 }
 489
 490 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 491   net_log_.AddEvent(
 492       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 493       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 494   ++num_packets_received_;
 495   if (largest_received_packet_sequence_number_ <
 496       header.packet_sequence_number) {
 497     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 498         largest_received_packet_sequence_number_;
 499     if (delta > 1) {
 500       // There is a gap between the largest packet previously received and
 501       // the current packet.  This indicates either loss, or out-of-order
 502       // delivery.
 503       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived",
 504                            static_cast<base::HistogramBase::Sample>(delta - 1));
 505     }
 506     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 507   }
 508   if (header.packet_sequence_number < received_packets_.size()) {
 509     received_packets_[static_cast<size_t>(header.packet_sequence_number)] =
 510         true;
 511   }
 512   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 513     ++num_out_of_order_received_packets_;
 514     if (previous_received_packet_size_ < last_received_packet_size_)
 515       ++num_out_of_order_large_received_packets_;
 516     UMA_HISTOGRAM_COUNTS(
 517         "Net.QuicSession.OutOfOrderGapReceived",
 518         static_cast<base::HistogramBase::Sample>(
 519             last_received_packet_sequence_number_ -
 520             header.packet_sequence_number));
 521   }
 522   last_received_packet_sequence_number_ = header.packet_sequence_number;
 523 }
 524
 525 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 526   net_log_.AddEvent(
 527       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 528       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 529 }
 530
 531 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 532   net_log_.AddEvent(
 533       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 534       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 535
 536   const size_t kApproximateLargestSoloAckBytes = 100;
 537   if (last_received_packet_sequence_number_ < received_acks_.size() &&
 538       last_received_packet_size_ < kApproximateLargestSoloAckBytes) {
 539     received_acks_[static_cast<size_t>(last_received_packet_sequence_number_)] =
 540         true;
 541   }
 542
 543   if (frame.is_truncated)
 544     ++num_truncated_acks_received_;
 545
 546   if (frame.missing_packets.empty())
 547     return;
 548
 549   SequenceNumberSet missing_packets = frame.missing_packets;
 550   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 551       largest_received_missing_packet_sequence_number_);
 552   if (it == missing_packets.end())
 553     return;
 554
 555   if (*it == largest_received_missing_packet_sequence_number_) {
 556     ++it;
 557     if (it == missing_packets.end())
 558       return;
 559   }
 560   // Scan through the list and log consecutive ranges of missing packets.
 561   size_t num_consecutive_missing_packets = 0;
 562   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 563   while (it != missing_packets.end()) {
 564     if (previous_missing_packet == *it - 1) {
 565       ++num_consecutive_missing_packets;
 566     } else {
 567       DCHECK_NE(0u, num_consecutive_missing_packets);
 568       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 569       // Make sure this packet it included in the count.
 570       num_consecutive_missing_packets = 1;
 571     }
 572     previous_missing_packet = *it;
 573     ++it;
 574   }
 575   if (num_consecutive_missing_packets != 0) {
 576     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 577   }
 578   largest_received_missing_packet_sequence_number_ =
 579         *missing_packets.rbegin();
 580 }
 581
 582 void QuicConnectionLogger::OnStopWaitingFrame(
 583     const QuicStopWaitingFrame& frame) {
 584   net_log_.AddEvent(
 585       NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
 586       base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
 587 }
 588
 589 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 590   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 591                               frame.error_code);
 592   net_log_.AddEvent(
 593       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 594       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 595 }
 596
 597 void QuicConnectionLogger::OnConnectionCloseFrame(
 598     const QuicConnectionCloseFrame& frame) {
 599   net_log_.AddEvent(
 600       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 601       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 602 }
 603
 604 void QuicConnectionLogger::OnWindowUpdateFrame(
 605     const QuicWindowUpdateFrame& frame) {
 606   net_log_.AddEvent(
 607       NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED,
 608       base::Bind(&NetLogQuicWindowUpdateFrameCallback, &frame));
 609 }
 610
 611 void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) {
 612   ++num_blocked_frames_received_;
 613   net_log_.AddEvent(
 614       NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
 615       base::Bind(&NetLogQuicBlockedFrameCallback, &frame));
 616 }
 617
 618 void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
 619   net_log_.AddEvent(
 620       NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
 621       base::Bind(&NetLogQuicGoAwayFrameCallback, &frame));
 622 }
 623
 624 void QuicConnectionLogger::OnPingFrame(const QuicPingFrame& frame) {
 625   // PingFrame has no contents to log, so just record that it was received.
 626   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_RECEIVED);
 627 }
 628
 629 void QuicConnectionLogger::OnPublicResetPacket(
 630     const QuicPublicResetPacket& packet) {
 631   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 632   UpdatePublicResetAddressMismatchHistogram(local_address_from_shlo_,
 633                                             packet.client_address);
 634 }
 635
 636 void QuicConnectionLogger::OnVersionNegotiationPacket(
 637     const QuicVersionNegotiationPacket& packet) {
 638   net_log_.AddEvent(
 639       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 640       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 641 }
 642
 643 void QuicConnectionLogger::OnRevivedPacket(
 644     const QuicPacketHeader& revived_header,
 645     base::StringPiece payload) {
 646   net_log_.AddEvent(
 647       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 648       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 649 }
 650
 651 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 652     const CryptoHandshakeMessage& message) {
 653   net_log_.AddEvent(
 654       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 655       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 656
 657   if (message.tag() == kSHLO) {
 658     StringPiece address;
 659     QuicSocketAddressCoder decoder;
 660     if (message.GetStringPiece(kCADR, &address) &&
 661         decoder.Decode(address.data(), address.size())) {
 662       local_address_from_shlo_ = IPEndPoint(decoder.ip(), decoder.port());
 663       UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromPeer",
 664                                 GetRealAddressFamily(
 665                                     local_address_from_shlo_.address()),
 666                                 ADDRESS_FAMILY_LAST);
 667     }
 668   }
 669 }
 670
 671 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 672     const CryptoHandshakeMessage& message) {
 673   net_log_.AddEvent(
 674       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 675       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 676 }
 677
 678 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 679                                               bool from_peer) {
 680   net_log_.AddEvent(
 681       NetLog::TYPE_QUIC_SESSION_CLOSED,
 682       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 683 }
 684
 685 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 686     const QuicVersion& version) {
 687   string quic_version = QuicVersionToString(version);
 688   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 689                     NetLog::StringCallback("version", &quic_version));
 690 }
 691
 692 void QuicConnectionLogger::UpdateReceivedFrameCounts(
 693     QuicStreamId stream_id,
 694     int num_frames_received,
 695     int num_duplicate_frames_received) {
 696   if (stream_id != kCryptoStreamId) {
 697     num_frames_received_ += num_frames_received;
 698     num_duplicate_frames_received_ += num_duplicate_frames_received;
 699   }
 700 }
 701
 702 void QuicConnectionLogger::OnCertificateVerified(
 703     const CertVerifyResult& result) {
 704   net_log_.AddEvent(
 705       NetLog::TYPE_QUIC_SESSION_CERTIFICATE_VERIFIED,
 706       base::Bind(&NetLogQuicCertificateVerifiedCallback, result.verified_cert));
 707 }
 708
 709 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram(
 710     const char* statistic_name) const {
 711   string prefix("Net.QuicSession.PacketReceived_");
 712   return base::LinearHistogram::FactoryGet(
 713       prefix + statistic_name + connection_description_,
 714       1, received_packets_.size(), received_packets_.size() + 1,
 715       base::HistogramBase::kUmaTargetedHistogramFlag);
 716 }
 717
 718 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
 719     const char* which_6) const {
 720   // This histogram takes a binary encoding of the 6 consecutive packets
 721   // received.  As a result, there are 64 possible sample-patterns.
 722   string prefix("Net.QuicSession.6PacketsPatternsReceived_");
 723   return base::LinearHistogram::FactoryGet(
 724       prefix + which_6 + connection_description_, 1, 64, 65,
 725       base::HistogramBase::kUmaTargetedHistogramFlag);
 726 }
 727
 728 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram(
 729   const char* which_21) const {
 730   // This histogram contains, for each sequence of 21 packets, the results from
 731   // 21 distinct questions about that sequence.  Conceptually the histogtram is
 732   // broken into 21 distinct ranges, and one sample is added into each of those
 733   // ranges whenever we process a set of 21 packets.
 734   // There is a little rendundancy, as each "range" must have the same number
 735   // of samples, all told, but the histogram is a tad easier to read this way.
 736   // The questions are:
 737   // Was the first packet present (bucket 0==>no; bucket 1==>yes)
 738   // Of the first two packets, how many were present? (bucket 2==> none;
 739   //   bucket 3==> 1 of 2; bucket 4==> 2 of 2)
 740   // Of the  first three packets, how many were present? (bucket 5==>none;
 741   //   bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3).
 742   // etc.
 743   string prefix("Net.QuicSession.21CumulativePacketsReceived_");
 744   return base::LinearHistogram::FactoryGet(
 745       prefix + which_21 + connection_description_,
 746       1, kBoundingSampleInCumulativeHistogram,
 747       kBoundingSampleInCumulativeHistogram + 1,
 748       base::HistogramBase::kUmaTargetedHistogramFlag);
 749 }
 750
 751 // static
 752 void QuicConnectionLogger::AddTo21CumulativeHistogram(
 753     base::HistogramBase* histogram,
 754     int bit_mask_of_packets,
 755     int valid_bits_in_mask) {
 756   DCHECK_LE(valid_bits_in_mask, 21);
 757   DCHECK_LT(bit_mask_of_packets, 1 << 21);
 758   const int blank_bits_in_mask = 21 - valid_bits_in_mask;
 759   DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0);
 760   bit_mask_of_packets >>= blank_bits_in_mask;
 761   int bits_so_far = 0;
 762   int range_start = 0;
 763   for (int i = 1; i <= valid_bits_in_mask; ++i) {
 764     bits_so_far += bit_mask_of_packets & 1;
 765     bit_mask_of_packets >>= 1;
 766     DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram);
 767     histogram->Add(range_start + bits_so_far);
 768     range_start += i + 1;
 769   }
 770 }
 771
 772 float QuicConnectionLogger::ReceivedPacketLossRate() const {
 773   if (largest_received_packet_sequence_number_ <= num_packets_received_)
 774     return 0.0f;
 775   return (largest_received_packet_sequence_number_ - num_packets_received_) /
 776          largest_received_packet_sequence_number_;
 777 }
 778
 779 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
 780   // For short connections under 22 packets in length, we'll rely on the
 781   // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
 782   // loss rates.  This way we avoid tremendously anomalous contributions to our
 783   // histogram.  (e.g., if we only got 5 packets, but lost 1, we'd otherwise
 784   // record a 20% loss in this histogram!). We may still get some strange data
 785   // (1 loss in 22 is still high :-/).
 786   if (largest_received_packet_sequence_number_ <= 21)
 787     return;
 788
 789   string prefix("Net.QuicSession.PacketLossRate_");
 790   base::HistogramBase* histogram = base::Histogram::FactoryGet(
 791       prefix + connection_description_, 1, 1000, 75,
 792       base::HistogramBase::kUmaTargetedHistogramFlag);
 793   histogram->Add(static_cast<base::HistogramBase::Sample>(
 794       ReceivedPacketLossRate() * 1000));
 795 }
 796
 797 void QuicConnectionLogger::RecordLossHistograms() const {
 798   if (largest_received_packet_sequence_number_ == 0)
 799     return;  // Connection was never used.
 800   RecordAggregatePacketLossRate();
 801
 802   base::HistogramBase* is_not_ack_histogram =
 803       GetPacketSequenceNumberHistogram("IsNotAck_");
 804   base::HistogramBase* is_an_ack_histogram =
 805       GetPacketSequenceNumberHistogram("IsAnAck_");
 806   base::HistogramBase* packet_arrived_histogram =
 807       GetPacketSequenceNumberHistogram("Ack_");
 808   base::HistogramBase* packet_missing_histogram =
 809       GetPacketSequenceNumberHistogram("Nack_");
 810   base::HistogramBase* ongoing_cumulative_packet_histogram =
 811       Get21CumulativeHistogram("Some21s_");
 812   base::HistogramBase* first_cumulative_packet_histogram =
 813       Get21CumulativeHistogram("First21_");
 814   base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_");
 815
 816   DCHECK_EQ(received_packets_.size(), received_acks_.size());
 817   const QuicPacketSequenceNumber last_index =
 818       std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1,
 819           largest_received_packet_sequence_number_);
 820   const QuicPacketSequenceNumber index_of_first_21_contribution =
 821       std::min<QuicPacketSequenceNumber>(21, last_index);
 822   // Bit pattern of consecutively received packets that is maintained as we scan
 823   // through the received_packets_ vector. Less significant bits correspond to
 824   // less recent packets, and only the low order 21 bits are ever defined.
 825   // Bit is 1 iff corresponding packet was received.
 826   int packet_pattern_21 = 0;
 827   // Zero is an invalid packet sequence number.
 828   DCHECK(!received_packets_[0]);
 829   for (size_t i = 1; i <= last_index; ++i) {
 830     if (received_acks_[i])
 831       is_an_ack_histogram->Add(i);
 832     else
 833       is_not_ack_histogram->Add(i);
 834
 835     packet_pattern_21 >>= 1;
 836     if (received_packets_[i]) {
 837       packet_arrived_histogram->Add(i);
 838       packet_pattern_21 |= (1 << 20);  // Turn on the 21st bit.
 839     } else {
 840       packet_missing_histogram->Add(i);
 841     }
 842
 843     if (i == index_of_first_21_contribution) {
 844       AddTo21CumulativeHistogram(first_cumulative_packet_histogram,
 845                                  packet_pattern_21, i);
 846     }
 847     // We'll just record for non-overlapping ranges, to reduce histogramming
 848     // cost for now.  Each call does 21 separate histogram additions.
 849     if (i > 21 || i % 21 == 0) {
 850       AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram,
 851                                  packet_pattern_21, 21);
 852     }
 853
 854     if (i < 6)
 855       continue;  // Not enough packets to do any pattern recording.
 856     int recent_6_mask = packet_pattern_21 >> 15;
 857     DCHECK_LT(recent_6_mask, 64);
 858     if (i == 6) {
 859       Get6PacketHistogram("First6_")->Add(recent_6_mask);
 860       continue;
 861     }
 862     // Record some overlapping patterns, to get a better picture, since this is
 863     // not very expensive.
 864     if (i % 3 == 0)
 865       six_packet_histogram->Add(recent_6_mask);
 866   }
 867 }
 868
 869 }  // namespace net