net/quic/quic_connection_logger.cc

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