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/strings/string_number_conversions.h"
  15 #include "base/values.h"
  16 #include "net/base/net_log.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/quic/crypto/crypto_handshake_message.h"
  21 #include "net/quic/crypto/crypto_protocol.h"
  22 #include "net/quic/quic_address_mismatch.h"
  23 #include "net/quic/quic_socket_address_coder.h"
  24
  25 using base::StringPiece;
  26 using std::string;
  27
  28 namespace net {
  29
  30 namespace {
  31
  32 // We have ranges-of-buckets in the cumulative histogram (covering 21 packet
  33 // sequences) of length 2, 3, 4, ... 22.
  34 // Hence the largest sample is bounded by the sum of those numbers.
  35 const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2;
  36
  37 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
  38                                       const IPEndPoint* peer_address,
  39                                       size_t packet_size,
  40                                       NetLog::LogLevel /* log_level */) {
  41   base::DictionaryValue* dict = new base::DictionaryValue();
  42   dict->SetString("self_address", self_address->ToString());
  43   dict->SetString("peer_address", peer_address->ToString());
  44   dict->SetInteger("size", packet_size);
  45   return dict;
  46 }
  47
  48 base::Value* NetLogQuicPacketSentCallback(
  49     QuicPacketSequenceNumber sequence_number,
  50     EncryptionLevel level,
  51     TransmissionType transmission_type,
  52     size_t packet_size,
  53     WriteResult result,
  54     NetLog::LogLevel /* log_level */) {
  55   base::DictionaryValue* dict = new base::DictionaryValue();
  56   dict->SetInteger("encryption_level", level);
  57   dict->SetInteger("transmission_type", transmission_type);
  58   dict->SetString("packet_sequence_number",
  59                   base::Uint64ToString(sequence_number));
  60   dict->SetInteger("size", packet_size);
  61   if (result.status != WRITE_STATUS_OK) {
  62     dict->SetInteger("net_error", result.error_code);
  63   }
  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", 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->SetBoolean("truncated", frame->is_truncated);
 110   base::ListValue* missing = new base::ListValue();
 111   dict->Set("missing_packets", missing);
 112   const SequenceNumberSet& missing_packets = frame->missing_packets;
 113   for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 114        it != missing_packets.end(); ++it) {
 115     missing->AppendString(base::Uint64ToString(*it));
 116   }
 117   return dict;
 118 }
 119
 120 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
 121     const QuicCongestionFeedbackFrame* frame,
 122     NetLog::LogLevel /* log_level */) {
 123   base::DictionaryValue* dict = new base::DictionaryValue();
 124   switch (frame->type) {
 125     case kTimestamp: {
 126       dict->SetString("type", "Timestamp");
 127       base::ListValue* received = new base::ListValue();
 128       dict->Set("received_packets", received);
 129       for (TimeMap::const_iterator it =
 130                frame->timestamp.received_packet_times.begin();
 131            it != frame->timestamp.received_packet_times.end(); ++it) {
 132         string value = base::Uint64ToString(it->first) + "@" +
 133             base::Uint64ToString(it->second.ToDebuggingValue());
 134         received->AppendString(value);
 135       }
 136       break;
 137     }
 138     case kTCP:
 139       dict->SetString("type", "TCP");
 140       dict->SetInteger("receive_window", frame->tcp.receive_window);
 141       break;
 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 const char* GetConnectionDescriptionString() {
 271   NetworkChangeNotifier::ConnectionType type =
 272       NetworkChangeNotifier::GetConnectionType();
 273   const char* description = NetworkChangeNotifier::ConnectionTypeToString(type);
 274   // Most platforms don't distingish Wifi vs Etherenet, and call everything
 275   // CONNECTION_UNKNOWN :-(.  We'll tease out some details when we are on WiFi,
 276   // and hopefully leave only ethernet (with no WiFi available) in the
 277   // CONNECTION_UNKNOWN category.  This *might* err if there is both ethernet,
 278   // as well as WiFi, where WiFi was not being used that much.
 279   // This function only seems usefully defined on Windows currently.
 280   if (type == NetworkChangeNotifier::CONNECTION_UNKNOWN ||
 281       type == NetworkChangeNotifier::CONNECTION_WIFI) {
 282     WifiPHYLayerProtocol wifi_type = GetWifiPHYLayerProtocol();
 283     switch (wifi_type) {
 284       case WIFI_PHY_LAYER_PROTOCOL_NONE:
 285         // No wifi support or no associated AP.
 286         break;
 287       case WIFI_PHY_LAYER_PROTOCOL_ANCIENT:
 288         // An obsolete modes introduced by the original 802.11, e.g. IR, FHSS.
 289         description = "CONNECTION_WIFI_ANCIENT";
 290         break;
 291       case WIFI_PHY_LAYER_PROTOCOL_A:
 292         // 802.11a, OFDM-based rates.
 293         description = "CONNECTION_WIFI_802.11a";
 294         break;
 295       case WIFI_PHY_LAYER_PROTOCOL_B:
 296         // 802.11b, DSSS or HR DSSS.
 297         description = "CONNECTION_WIFI_802.11b";
 298         break;
 299       case WIFI_PHY_LAYER_PROTOCOL_G:
 300         // 802.11g, same rates as 802.11a but compatible with 802.11b.
 301         description = "CONNECTION_WIFI_802.11g";
 302         break;
 303       case WIFI_PHY_LAYER_PROTOCOL_N:
 304         // 802.11n, HT rates.
 305         description = "CONNECTION_WIFI_802.11n";
 306         break;
 307       case WIFI_PHY_LAYER_PROTOCOL_UNKNOWN:
 308         // Unclassified mode or failure to identify.
 309         break;
 310     }
 311   }
 312   return description;
 313 }
 314
 315 // If |address| is an IPv4-mapped IPv6 address, returns ADDRESS_FAMILY_IPV4
 316 // instead of ADDRESS_FAMILY_IPV6. Othewise, behaves like GetAddressFamily().
 317 AddressFamily GetRealAddressFamily(const IPAddressNumber& address) {
 318   return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 :
 319       GetAddressFamily(address);
 320 }
 321
 322 }  // namespace
 323
 324 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
 325     : net_log_(net_log),
 326       last_received_packet_sequence_number_(0),
 327       last_received_packet_size_(0),
 328       largest_received_packet_sequence_number_(0),
 329       largest_received_missing_packet_sequence_number_(0),
 330       num_out_of_order_received_packets_(0),
 331       num_packets_received_(0),
 332       num_truncated_acks_sent_(0),
 333       num_truncated_acks_received_(0),
 334       num_frames_received_(0),
 335       num_duplicate_frames_received_(0),
 336       connection_description_(GetConnectionDescriptionString()) {
 337 }
 338
 339 QuicConnectionLogger::~QuicConnectionLogger() {
 340   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
 341                        num_out_of_order_received_packets_);
 342   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
 343                        num_truncated_acks_sent_);
 344   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
 345                        num_truncated_acks_received_);
 346   if (num_frames_received_ > 0) {
 347     int duplicate_stream_frame_per_thousand =
 348         num_duplicate_frames_received_ * 1000 / num_frames_received_;
 349     if (num_packets_received_ < 100) {
 350       UMA_HISTOGRAM_CUSTOM_COUNTS(
 351           "Net.QuicSession.StreamFrameDuplicatedShortConnection",
 352           duplicate_stream_frame_per_thousand, 1, 1000, 75);
 353     } else {
 354       UMA_HISTOGRAM_CUSTOM_COUNTS(
 355           "Net.QuicSession.StreamFrameDuplicatedLongConnection",
 356           duplicate_stream_frame_per_thousand, 1, 1000, 75);
 357
 358     }
 359   }
 360
 361   RecordLossHistograms();
 362 }
 363
 364 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
 365   switch (frame.type) {
 366     case PADDING_FRAME:
 367       break;
 368     case STREAM_FRAME:
 369       net_log_.AddEvent(
 370           NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
 371           base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
 372       break;
 373     case ACK_FRAME:
 374       net_log_.AddEvent(
 375           NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
 376           base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
 377       if (frame.ack_frame->is_truncated)
 378         ++num_truncated_acks_sent_;
 379       break;
 380     case CONGESTION_FEEDBACK_FRAME:
 381       net_log_.AddEvent(
 382           NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
 383           base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
 384                      frame.congestion_feedback_frame));
 385       break;
 386     case RST_STREAM_FRAME:
 387       UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
 388                                   frame.rst_stream_frame->error_code);
 389       net_log_.AddEvent(
 390           NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
 391           base::Bind(&NetLogQuicRstStreamFrameCallback,
 392                      frame.rst_stream_frame));
 393       break;
 394     case CONNECTION_CLOSE_FRAME:
 395       net_log_.AddEvent(
 396           NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
 397           base::Bind(&NetLogQuicConnectionCloseFrameCallback,
 398                      frame.connection_close_frame));
 399       break;
 400     case GOAWAY_FRAME:
 401       net_log_.AddEvent(
 402           NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_SENT,
 403           base::Bind(&NetLogQuicGoAwayFrameCallback,
 404                      frame.goaway_frame));
 405       break;
 406     case WINDOW_UPDATE_FRAME:
 407       net_log_.AddEvent(
 408           NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT,
 409           base::Bind(&NetLogQuicWindowUpdateFrameCallback,
 410                      frame.window_update_frame));
 411       break;
 412     case BLOCKED_FRAME:
 413       net_log_.AddEvent(
 414           NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT,
 415           base::Bind(&NetLogQuicBlockedFrameCallback,
 416                      frame.blocked_frame));
 417       break;
 418     case STOP_WAITING_FRAME:
 419       net_log_.AddEvent(
 420           NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT,
 421           base::Bind(&NetLogQuicStopWaitingFrameCallback,
 422                      frame.stop_waiting_frame));
 423       break;
 424     case PING_FRAME:
 425       // PingFrame has no contents to log, so just record that it was sent.
 426       net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_SENT);
 427       break;
 428     default:
 429       DCHECK(false) << "Illegal frame type: " << frame.type;
 430   }
 431 }
 432
 433 void QuicConnectionLogger::OnPacketSent(
 434     QuicPacketSequenceNumber sequence_number,
 435     EncryptionLevel level,
 436     TransmissionType transmission_type,
 437     const QuicEncryptedPacket& packet,
 438     WriteResult result) {
 439   net_log_.AddEvent(
 440       NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 441       base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
 442                  transmission_type, packet.length(), result));
 443 }
 444
 445 void QuicConnectionLogger:: OnPacketRetransmitted(
 446       QuicPacketSequenceNumber old_sequence_number,
 447       QuicPacketSequenceNumber new_sequence_number) {
 448   net_log_.AddEvent(
 449       NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 450       base::Bind(&NetLogQuicPacketRetransmittedCallback,
 451                  old_sequence_number, new_sequence_number));
 452 }
 453
 454 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 455                                             const IPEndPoint& peer_address,
 456                                             const QuicEncryptedPacket& packet) {
 457   if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) {
 458     local_address_from_self_ = self_address;
 459     UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromSelf",
 460                               GetRealAddressFamily(self_address.address()),
 461                               ADDRESS_FAMILY_LAST);
 462   }
 463
 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::OnProtocolVersionMismatch(
 472     QuicVersion received_version) {
 473   // TODO(rtenneti): Add logging.
 474 }
 475
 476 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 477   net_log_.AddEvent(
 478       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 479       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 480   ++num_packets_received_;
 481   if (largest_received_packet_sequence_number_ <
 482       header.packet_sequence_number) {
 483     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 484         largest_received_packet_sequence_number_;
 485     if (delta > 1) {
 486       // There is a gap between the largest packet previously received and
 487       // the current packet.  This indicates either loss, or out-of-order
 488       // delivery.
 489       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
 490     }
 491     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 492   }
 493   if (header.packet_sequence_number < received_packets_.size())
 494     received_packets_[header.packet_sequence_number] = true;
 495   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 496     ++num_out_of_order_received_packets_;
 497     UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
 498                          last_received_packet_sequence_number_ -
 499                              header.packet_sequence_number);
 500   }
 501   last_received_packet_sequence_number_ = header.packet_sequence_number;
 502 }
 503
 504 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 505   net_log_.AddEvent(
 506       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 507       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 508 }
 509
 510 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 511   net_log_.AddEvent(
 512       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 513       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 514
 515   const size_t kApproximateLargestSoloAckBytes = 100;
 516   if (last_received_packet_sequence_number_ < received_acks_.size() &&
 517       last_received_packet_size_ < kApproximateLargestSoloAckBytes)
 518     received_acks_[last_received_packet_sequence_number_] = true;
 519
 520   if (frame.is_truncated)
 521     ++num_truncated_acks_received_;
 522
 523   if (frame.missing_packets.empty())
 524     return;
 525
 526   SequenceNumberSet missing_packets = frame.missing_packets;
 527   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 528       largest_received_missing_packet_sequence_number_);
 529   if (it == missing_packets.end())
 530     return;
 531
 532   if (*it == largest_received_missing_packet_sequence_number_) {
 533     ++it;
 534     if (it == missing_packets.end())
 535       return;
 536   }
 537   // Scan through the list and log consecutive ranges of missing packets.
 538   size_t num_consecutive_missing_packets = 0;
 539   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 540   while (it != missing_packets.end()) {
 541     if (previous_missing_packet == *it - 1) {
 542       ++num_consecutive_missing_packets;
 543     } else {
 544       DCHECK_NE(0u, num_consecutive_missing_packets);
 545       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 546       // Make sure this packet it included in the count.
 547       num_consecutive_missing_packets = 1;
 548     }
 549     previous_missing_packet = *it;
 550     ++it;
 551   }
 552   if (num_consecutive_missing_packets != 0) {
 553     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 554   }
 555   largest_received_missing_packet_sequence_number_ =
 556         *missing_packets.rbegin();
 557 }
 558
 559 void QuicConnectionLogger::OnCongestionFeedbackFrame(
 560     const QuicCongestionFeedbackFrame& frame) {
 561   net_log_.AddEvent(
 562       NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
 563       base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
 564 }
 565
 566 void QuicConnectionLogger::OnStopWaitingFrame(
 567     const QuicStopWaitingFrame& frame) {
 568   net_log_.AddEvent(
 569       NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
 570       base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
 571 }
 572
 573 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 574   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 575                               frame.error_code);
 576   net_log_.AddEvent(
 577       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 578       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 579 }
 580
 581 void QuicConnectionLogger::OnConnectionCloseFrame(
 582     const QuicConnectionCloseFrame& frame) {
 583   net_log_.AddEvent(
 584       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 585       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 586 }
 587
 588 void QuicConnectionLogger::OnWindowUpdateFrame(
 589     const QuicWindowUpdateFrame& frame) {
 590   net_log_.AddEvent(
 591       NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED,
 592       base::Bind(&NetLogQuicWindowUpdateFrameCallback, &frame));
 593 }
 594
 595 void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) {
 596   net_log_.AddEvent(
 597       NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
 598       base::Bind(&NetLogQuicBlockedFrameCallback, &frame));
 599 }
 600
 601 void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
 602   net_log_.AddEvent(
 603       NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
 604       base::Bind(&NetLogQuicGoAwayFrameCallback, &frame));
 605 }
 606
 607 void QuicConnectionLogger::OnPingFrame(const QuicPingFrame& frame) {
 608   // PingFrame has no contents to log, so just record that it was received.
 609   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_RECEIVED);
 610 }
 611
 612 void QuicConnectionLogger::OnPublicResetPacket(
 613     const QuicPublicResetPacket& packet) {
 614   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 615   UpdatePublicResetAddressMismatchHistogram(local_address_from_shlo_,
 616                                             packet.client_address);
 617 }
 618
 619 void QuicConnectionLogger::OnVersionNegotiationPacket(
 620     const QuicVersionNegotiationPacket& packet) {
 621   net_log_.AddEvent(
 622       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 623       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 624 }
 625
 626 void QuicConnectionLogger::OnRevivedPacket(
 627     const QuicPacketHeader& revived_header,
 628     base::StringPiece payload) {
 629   net_log_.AddEvent(
 630       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 631       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 632 }
 633
 634 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 635     const CryptoHandshakeMessage& message) {
 636   net_log_.AddEvent(
 637       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 638       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 639
 640   if (message.tag() == kSHLO) {
 641     StringPiece address;
 642     QuicSocketAddressCoder decoder;
 643     if (message.GetStringPiece(kCADR, &address) &&
 644         decoder.Decode(address.data(), address.size())) {
 645       local_address_from_shlo_ = IPEndPoint(decoder.ip(), decoder.port());
 646       UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromPeer",
 647                                 GetRealAddressFamily(
 648                                     local_address_from_shlo_.address()),
 649                                 ADDRESS_FAMILY_LAST);
 650     }
 651   }
 652 }
 653
 654 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 655     const CryptoHandshakeMessage& message) {
 656   net_log_.AddEvent(
 657       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 658       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 659 }
 660
 661 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 662                                               bool from_peer) {
 663   net_log_.AddEvent(
 664       NetLog::TYPE_QUIC_SESSION_CLOSED,
 665       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 666 }
 667
 668 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 669     const QuicVersion& version) {
 670   string quic_version = QuicVersionToString(version);
 671   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 672                     NetLog::StringCallback("version", &quic_version));
 673 }
 674
 675 void QuicConnectionLogger::UpdateReceivedFrameCounts(
 676     QuicStreamId stream_id,
 677     int num_frames_received,
 678     int num_duplicate_frames_received) {
 679   if (stream_id != kCryptoStreamId) {
 680     num_frames_received_ += num_frames_received;
 681     num_duplicate_frames_received_ += num_duplicate_frames_received;
 682   }
 683 }
 684
 685 void QuicConnectionLogger::OnCertificateVerified(
 686     const CertVerifyResult& result) {
 687   net_log_.AddEvent(
 688       NetLog::TYPE_QUIC_SESSION_CERTIFICATE_VERIFIED,
 689       base::Bind(&NetLogQuicCertificateVerifiedCallback, result.verified_cert));
 690 }
 691
 692 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram(
 693     const char* statistic_name) const {
 694   string prefix("Net.QuicSession.PacketReceived_");
 695   return base::LinearHistogram::FactoryGet(
 696       prefix + statistic_name + connection_description_,
 697       1, received_packets_.size(), received_packets_.size() + 1,
 698       base::HistogramBase::kUmaTargetedHistogramFlag);
 699 }
 700
 701 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
 702     const char* which_6) const {
 703   // This histogram takes a binary encoding of the 6 consecutive packets
 704   // received.  As a result, there are 64 possible sample-patterns.
 705   string prefix("Net.QuicSession.6PacketsPatternsReceived_");
 706   return base::LinearHistogram::FactoryGet(
 707       prefix + which_6 + connection_description_, 1, 64, 65,
 708       base::HistogramBase::kUmaTargetedHistogramFlag);
 709 }
 710
 711 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram(
 712   const char* which_21) const {
 713   // This histogram contains, for each sequence of 21 packets, the results from
 714   // 21 distinct questions about that sequence.  Conceptually the histogtram is
 715   // broken into 21 distinct ranges, and one sample is added into each of those
 716   // ranges whenever we process a set of 21 packets.
 717   // There is a little rendundancy, as each "range" must have the same number
 718   // of samples, all told, but the histogram is a tad easier to read this way.
 719   // The questions are:
 720   // Was the first packet present (bucket 0==>no; bucket 1==>yes)
 721   // Of the first two packets, how many were present? (bucket 2==> none;
 722   //   bucket 3==> 1 of 2; bucket 4==> 2 of 2)
 723   // Of the  first three packets, how many were present? (bucket 5==>none;
 724   //   bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3).
 725   // etc.
 726   string prefix("Net.QuicSession.21CumulativePacketsReceived_");
 727   return base::LinearHistogram::FactoryGet(
 728       prefix + which_21 + connection_description_,
 729       1, kBoundingSampleInCumulativeHistogram,
 730       kBoundingSampleInCumulativeHistogram + 1,
 731       base::HistogramBase::kUmaTargetedHistogramFlag);
 732 }
 733
 734 // static
 735 void QuicConnectionLogger::AddTo21CumulativeHistogram(
 736     base::HistogramBase* histogram,
 737     int bit_mask_of_packets,
 738     int valid_bits_in_mask) {
 739   DCHECK_LE(valid_bits_in_mask, 21);
 740   DCHECK_LT(bit_mask_of_packets, 1 << 21);
 741   const int blank_bits_in_mask = 21 - valid_bits_in_mask;
 742   DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0);
 743   bit_mask_of_packets >>= blank_bits_in_mask;
 744   int bits_so_far = 0;
 745   int range_start = 0;
 746   for (int i = 1; i <= valid_bits_in_mask; ++i) {
 747     bits_so_far += bit_mask_of_packets & 1;
 748     bit_mask_of_packets >>= 1;
 749     DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram);
 750     histogram->Add(range_start + bits_so_far);
 751     range_start += i + 1;
 752   }
 753 }
 754
 755 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
 756   // For short connections under 22 packets in length, we'll rely on the
 757   // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
 758   // loss rates.  This way we avoid tremendously anomalous contributions to our
 759   // histogram.  (e.g., if we only got 5 packets, but lost 1, we'd otherwise
 760   // record a 20% loss in this histogram!). We may still get some strange data
 761   // (1 loss in 22 is still high :-/).
 762   if (largest_received_packet_sequence_number_ <= 21)
 763     return;
 764
 765   QuicPacketSequenceNumber divisor = largest_received_packet_sequence_number_;
 766   QuicPacketSequenceNumber numerator = divisor - num_packets_received_;
 767   if (divisor < 100000)
 768     numerator *= 1000;
 769   else
 770     divisor /= 1000;
 771   string prefix("Net.QuicSession.PacketLossRate_");
 772   base::HistogramBase* histogram = base::Histogram::FactoryGet(
 773       prefix + connection_description_, 1, 1000, 75,
 774       base::HistogramBase::kUmaTargetedHistogramFlag);
 775   histogram->Add(numerator / divisor);
 776 }
 777
 778 void QuicConnectionLogger::RecordLossHistograms() const {
 779   if (largest_received_packet_sequence_number_ == 0)
 780     return;  // Connection was never used.
 781   RecordAggregatePacketLossRate();
 782
 783   base::HistogramBase* is_not_ack_histogram =
 784       GetPacketSequenceNumberHistogram("IsNotAck_");
 785   base::HistogramBase* is_an_ack_histogram =
 786       GetPacketSequenceNumberHistogram("IsAnAck_");
 787   base::HistogramBase* packet_arrived_histogram =
 788       GetPacketSequenceNumberHistogram("Ack_");
 789   base::HistogramBase* packet_missing_histogram =
 790       GetPacketSequenceNumberHistogram("Nack_");
 791   base::HistogramBase* ongoing_cumulative_packet_histogram =
 792       Get21CumulativeHistogram("Some21s_");
 793   base::HistogramBase* first_cumulative_packet_histogram =
 794       Get21CumulativeHistogram("First21_");
 795   base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_");
 796
 797   DCHECK_EQ(received_packets_.size(), received_acks_.size());
 798   const QuicPacketSequenceNumber last_index =
 799       std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1,
 800           largest_received_packet_sequence_number_);
 801   const QuicPacketSequenceNumber index_of_first_21_contribution =
 802       std::min<QuicPacketSequenceNumber>(21, last_index);
 803   // Bit pattern of consecutively received packets that is maintained as we scan
 804   // through the received_packets_ vector. Less significant bits correspond to
 805   // less recent packets, and only the low order 21 bits are ever defined.
 806   // Bit is 1 iff corresponding packet was received.
 807   int packet_pattern_21 = 0;
 808   // Zero is an invalid packet sequence number.
 809   DCHECK(!received_packets_[0]);
 810   for (size_t i = 1; i <= last_index; ++i) {
 811     if (received_acks_[i])
 812       is_an_ack_histogram->Add(i);
 813     else
 814       is_not_ack_histogram->Add(i);
 815
 816     packet_pattern_21 >>= 1;
 817     if (received_packets_[i]) {
 818       packet_arrived_histogram->Add(i);
 819       packet_pattern_21 |= (1 << 20);  // Turn on the 21st bit.
 820     } else {
 821       packet_missing_histogram->Add(i);
 822     }
 823
 824     if (i == index_of_first_21_contribution) {
 825       AddTo21CumulativeHistogram(first_cumulative_packet_histogram,
 826                                  packet_pattern_21, i);
 827     }
 828     // We'll just record for non-overlapping ranges, to reduce histogramming
 829     // cost for now.  Each call does 21 separate histogram additions.
 830     if (i > 21 || i % 21 == 0) {
 831       AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram,
 832                                  packet_pattern_21, 21);
 833     }
 834
 835     if (i < 6)
 836       continue;  // Not enough packets to do any pattern recording.
 837     int recent_6_mask = packet_pattern_21 >> 15;
 838     DCHECK_LT(recent_6_mask, 64);
 839     if (i == 6) {
 840       Get6PacketHistogram("First6_")->Add(recent_6_mask);
 841       continue;
 842     }
 843     // Record some overlapping patterns, to get a better picture, since this is
 844     // not very expensive.
 845     if (i % 3 == 0)
 846       six_packet_histogram->Add(recent_6_mask);
 847   }
 848 }
 849
 850 }  // namespace net