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