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