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