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