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     case MTU_DISCOVERY_FRAME:
 432       // MtuDiscoveryFrame is PingFrame on wire, it does not have any payload.
 433       net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_MTU_DISCOVERY_FRAME_SENT);
 434       break;
 435     default:
 436       DCHECK(false) << "Illegal frame type: " << frame.type;
 437   }
 438 }
 439
 440 void QuicConnectionLogger::OnPacketSent(
 441     const SerializedPacket& serialized_packet,
 442     QuicPacketSequenceNumber original_sequence_number,
 443     EncryptionLevel level,
 444     TransmissionType transmission_type,
 445     const QuicEncryptedPacket& packet,
 446     QuicTime sent_time) {
 447   if (original_sequence_number == 0) {
 448     net_log_.AddEvent(
 449         NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 450         base::Bind(&NetLogQuicPacketSentCallback, serialized_packet,
 451                    level, transmission_type, packet.length(), sent_time));
 452   }  else {
 453     net_log_.AddEvent(
 454         NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 455         base::Bind(&NetLogQuicPacketRetransmittedCallback,
 456                    original_sequence_number,
 457                    serialized_packet.sequence_number));
 458   }
 459 }
 460
 461 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 462                                             const IPEndPoint& peer_address,
 463                                             const QuicEncryptedPacket& packet) {
 464   if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) {
 465     local_address_from_self_ = self_address;
 466     UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromSelf",
 467                               GetRealAddressFamily(self_address.address()),
 468                               ADDRESS_FAMILY_LAST);
 469   }
 470
 471   previous_received_packet_size_ = last_received_packet_size_;
 472   last_received_packet_size_ = packet.length();
 473   net_log_.AddEvent(
 474       NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
 475       base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
 476                  packet.length()));
 477 }
 478
 479 void QuicConnectionLogger::OnIncorrectConnectionId(
 480     QuicConnectionId connection_id) {
 481   ++num_incorrect_connection_ids_;
 482 }
 483
 484 void QuicConnectionLogger::OnUndecryptablePacket() {
 485   ++num_undecryptable_packets_;
 486 }
 487
 488 void QuicConnectionLogger::OnDuplicatePacket(
 489     QuicPacketSequenceNumber sequence_number) {
 490   ++num_duplicate_packets_;
 491 }
 492
 493 void QuicConnectionLogger::OnProtocolVersionMismatch(
 494     QuicVersion received_version) {
 495   // TODO(rtenneti): Add logging.
 496 }
 497
 498 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 499   net_log_.AddEvent(
 500       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 501       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 502   ++num_packets_received_;
 503   if (largest_received_packet_sequence_number_ <
 504       header.packet_sequence_number) {
 505     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 506         largest_received_packet_sequence_number_;
 507     if (delta > 1) {
 508       // There is a gap between the largest packet previously received and
 509       // the current packet.  This indicates either loss, or out-of-order
 510       // delivery.
 511       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived",
 512                            static_cast<base::HistogramBase::Sample>(delta - 1));
 513     }
 514     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 515   }
 516   if (header.packet_sequence_number < received_packets_.size()) {
 517     received_packets_[static_cast<size_t>(header.packet_sequence_number)] =
 518         true;
 519   }
 520   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 521     ++num_out_of_order_received_packets_;
 522     if (previous_received_packet_size_ < last_received_packet_size_)
 523       ++num_out_of_order_large_received_packets_;
 524     UMA_HISTOGRAM_COUNTS(
 525         "Net.QuicSession.OutOfOrderGapReceived",
 526         static_cast<base::HistogramBase::Sample>(
 527             last_received_packet_sequence_number_ -
 528             header.packet_sequence_number));
 529   }
 530   last_received_packet_sequence_number_ = header.packet_sequence_number;
 531 }
 532
 533 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 534   net_log_.AddEvent(
 535       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 536       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 537 }
 538
 539 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 540   net_log_.AddEvent(
 541       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 542       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 543
 544   const size_t kApproximateLargestSoloAckBytes = 100;
 545   if (last_received_packet_sequence_number_ < received_acks_.size() &&
 546       last_received_packet_size_ < kApproximateLargestSoloAckBytes) {
 547     received_acks_[static_cast<size_t>(last_received_packet_sequence_number_)] =
 548         true;
 549   }
 550
 551   if (frame.is_truncated)
 552     ++num_truncated_acks_received_;
 553
 554   if (frame.missing_packets.empty())
 555     return;
 556
 557   SequenceNumberSet missing_packets = frame.missing_packets;
 558   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 559       largest_received_missing_packet_sequence_number_);
 560   if (it == missing_packets.end())
 561     return;
 562
 563   if (*it == largest_received_missing_packet_sequence_number_) {
 564     ++it;
 565     if (it == missing_packets.end())
 566       return;
 567   }
 568   // Scan through the list and log consecutive ranges of missing packets.
 569   size_t num_consecutive_missing_packets = 0;
 570   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 571   while (it != missing_packets.end()) {
 572     if (previous_missing_packet == *it - 1) {
 573       ++num_consecutive_missing_packets;
 574     } else {
 575       DCHECK_NE(0u, num_consecutive_missing_packets);
 576       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 577       // Make sure this packet it included in the count.
 578       num_consecutive_missing_packets = 1;
 579     }
 580     previous_missing_packet = *it;
 581     ++it;
 582   }
 583   if (num_consecutive_missing_packets != 0) {
 584     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 585   }
 586   largest_received_missing_packet_sequence_number_ =
 587         *missing_packets.rbegin();
 588 }
 589
 590 void QuicConnectionLogger::OnStopWaitingFrame(
 591     const QuicStopWaitingFrame& frame) {
 592   net_log_.AddEvent(
 593       NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
 594       base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
 595 }
 596
 597 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 598   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 599                               frame.error_code);
 600   net_log_.AddEvent(
 601       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 602       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 603 }
 604
 605 void QuicConnectionLogger::OnConnectionCloseFrame(
 606     const QuicConnectionCloseFrame& frame) {
 607   net_log_.AddEvent(
 608       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 609       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 610 }
 611
 612 void QuicConnectionLogger::OnWindowUpdateFrame(
 613     const QuicWindowUpdateFrame& frame) {
 614   net_log_.AddEvent(
 615       NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED,
 616       base::Bind(&NetLogQuicWindowUpdateFrameCallback, &frame));
 617 }
 618
 619 void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) {
 620   ++num_blocked_frames_received_;
 621   net_log_.AddEvent(
 622       NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
 623       base::Bind(&NetLogQuicBlockedFrameCallback, &frame));
 624 }
 625
 626 void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
 627   net_log_.AddEvent(
 628       NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
 629       base::Bind(&NetLogQuicGoAwayFrameCallback, &frame));
 630 }
 631
 632 void QuicConnectionLogger::OnPingFrame(const QuicPingFrame& frame) {
 633   // PingFrame has no contents to log, so just record that it was received.
 634   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_RECEIVED);
 635 }
 636
 637 void QuicConnectionLogger::OnPublicResetPacket(
 638     const QuicPublicResetPacket& packet) {
 639   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 640   UpdatePublicResetAddressMismatchHistogram(local_address_from_shlo_,
 641                                             packet.client_address);
 642 }
 643
 644 void QuicConnectionLogger::OnVersionNegotiationPacket(
 645     const QuicVersionNegotiationPacket& packet) {
 646   net_log_.AddEvent(
 647       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 648       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 649 }
 650
 651 void QuicConnectionLogger::OnRevivedPacket(
 652     const QuicPacketHeader& revived_header,
 653     base::StringPiece payload) {
 654   net_log_.AddEvent(
 655       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 656       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 657 }
 658
 659 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 660     const CryptoHandshakeMessage& message) {
 661   net_log_.AddEvent(
 662       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 663       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 664
 665   if (message.tag() == kSHLO) {
 666     StringPiece address;
 667     QuicSocketAddressCoder decoder;
 668     if (message.GetStringPiece(kCADR, &address) &&
 669         decoder.Decode(address.data(), address.size())) {
 670       local_address_from_shlo_ = IPEndPoint(decoder.ip(), decoder.port());
 671       UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromPeer",
 672                                 GetRealAddressFamily(
 673                                     local_address_from_shlo_.address()),
 674                                 ADDRESS_FAMILY_LAST);
 675     }
 676   }
 677 }
 678
 679 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 680     const CryptoHandshakeMessage& message) {
 681   net_log_.AddEvent(
 682       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 683       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 684 }
 685
 686 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 687                                               bool from_peer) {
 688   net_log_.AddEvent(
 689       NetLog::TYPE_QUIC_SESSION_CLOSED,
 690       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 691 }
 692
 693 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 694     const QuicVersion& version) {
 695   string quic_version = QuicVersionToString(version);
 696   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 697                     NetLog::StringCallback("version", &quic_version));
 698 }
 699
 700 void QuicConnectionLogger::UpdateReceivedFrameCounts(
 701     QuicStreamId stream_id,
 702     int num_frames_received,
 703     int num_duplicate_frames_received) {
 704   if (stream_id != kCryptoStreamId) {
 705     num_frames_received_ += num_frames_received;
 706     num_duplicate_frames_received_ += num_duplicate_frames_received;
 707   }
 708 }
 709
 710 void QuicConnectionLogger::OnCertificateVerified(
 711     const CertVerifyResult& result) {
 712   net_log_.AddEvent(
 713       NetLog::TYPE_QUIC_SESSION_CERTIFICATE_VERIFIED,
 714       base::Bind(&NetLogQuicCertificateVerifiedCallback, result.verified_cert));
 715 }
 716
 717 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram(
 718     const char* statistic_name) const {
 719   string prefix("Net.QuicSession.PacketReceived_");
 720   return base::LinearHistogram::FactoryGet(
 721       prefix + statistic_name + connection_description_,
 722       1, received_packets_.size(), received_packets_.size() + 1,
 723       base::HistogramBase::kUmaTargetedHistogramFlag);
 724 }
 725
 726 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
 727     const char* which_6) const {
 728   // This histogram takes a binary encoding of the 6 consecutive packets
 729   // received.  As a result, there are 64 possible sample-patterns.
 730   string prefix("Net.QuicSession.6PacketsPatternsReceived_");
 731   return base::LinearHistogram::FactoryGet(
 732       prefix + which_6 + connection_description_, 1, 64, 65,
 733       base::HistogramBase::kUmaTargetedHistogramFlag);
 734 }
 735
 736 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram(
 737   const char* which_21) const {
 738   // This histogram contains, for each sequence of 21 packets, the results from
 739   // 21 distinct questions about that sequence.  Conceptually the histogtram is
 740   // broken into 21 distinct ranges, and one sample is added into each of those
 741   // ranges whenever we process a set of 21 packets.
 742   // There is a little rendundancy, as each "range" must have the same number
 743   // of samples, all told, but the histogram is a tad easier to read this way.
 744   // The questions are:
 745   // Was the first packet present (bucket 0==>no; bucket 1==>yes)
 746   // Of the first two packets, how many were present? (bucket 2==> none;
 747   //   bucket 3==> 1 of 2; bucket 4==> 2 of 2)
 748   // Of the  first three packets, how many were present? (bucket 5==>none;
 749   //   bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3).
 750   // etc.
 751   string prefix("Net.QuicSession.21CumulativePacketsReceived_");
 752   return base::LinearHistogram::FactoryGet(
 753       prefix + which_21 + connection_description_,
 754       1, kBoundingSampleInCumulativeHistogram,
 755       kBoundingSampleInCumulativeHistogram + 1,
 756       base::HistogramBase::kUmaTargetedHistogramFlag);
 757 }
 758
 759 // static
 760 void QuicConnectionLogger::AddTo21CumulativeHistogram(
 761     base::HistogramBase* histogram,
 762     int bit_mask_of_packets,
 763     int valid_bits_in_mask) {
 764   DCHECK_LE(valid_bits_in_mask, 21);
 765   DCHECK_LT(bit_mask_of_packets, 1 << 21);
 766   const int blank_bits_in_mask = 21 - valid_bits_in_mask;
 767   DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0);
 768   bit_mask_of_packets >>= blank_bits_in_mask;
 769   int bits_so_far = 0;
 770   int range_start = 0;
 771   for (int i = 1; i <= valid_bits_in_mask; ++i) {
 772     bits_so_far += bit_mask_of_packets & 1;
 773     bit_mask_of_packets >>= 1;
 774     DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram);
 775     histogram->Add(range_start + bits_so_far);
 776     range_start += i + 1;
 777   }
 778 }
 779
 780 float QuicConnectionLogger::ReceivedPacketLossRate() const {
 781   if (largest_received_packet_sequence_number_ <= num_packets_received_)
 782     return 0.0f;
 783   float num_received =
 784       largest_received_packet_sequence_number_ - num_packets_received_;
 785   return num_received / largest_received_packet_sequence_number_;
 786 }
 787
 788 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
 789   // For short connections under 22 packets in length, we'll rely on the
 790   // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
 791   // loss rates.  This way we avoid tremendously anomalous contributions to our
 792   // histogram.  (e.g., if we only got 5 packets, but lost 1, we'd otherwise
 793   // record a 20% loss in this histogram!). We may still get some strange data
 794   // (1 loss in 22 is still high :-/).
 795   if (largest_received_packet_sequence_number_ <= 21)
 796     return;
 797
 798   string prefix("Net.QuicSession.PacketLossRate_");
 799   base::HistogramBase* histogram = base::Histogram::FactoryGet(
 800       prefix + connection_description_, 1, 1000, 75,
 801       base::HistogramBase::kUmaTargetedHistogramFlag);
 802   histogram->Add(static_cast<base::HistogramBase::Sample>(
 803       ReceivedPacketLossRate() * 1000));
 804 }
 805
 806 void QuicConnectionLogger::RecordLossHistograms() const {
 807   if (largest_received_packet_sequence_number_ == 0)
 808     return;  // Connection was never used.
 809   RecordAggregatePacketLossRate();
 810
 811   base::HistogramBase* is_not_ack_histogram =
 812       GetPacketSequenceNumberHistogram("IsNotAck_");
 813   base::HistogramBase* is_an_ack_histogram =
 814       GetPacketSequenceNumberHistogram("IsAnAck_");
 815   base::HistogramBase* packet_arrived_histogram =
 816       GetPacketSequenceNumberHistogram("Ack_");
 817   base::HistogramBase* packet_missing_histogram =
 818       GetPacketSequenceNumberHistogram("Nack_");
 819   base::HistogramBase* ongoing_cumulative_packet_histogram =
 820       Get21CumulativeHistogram("Some21s_");
 821   base::HistogramBase* first_cumulative_packet_histogram =
 822       Get21CumulativeHistogram("First21_");
 823   base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_");
 824
 825   DCHECK_EQ(received_packets_.size(), received_acks_.size());
 826   const QuicPacketSequenceNumber last_index =
 827       std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1,
 828           largest_received_packet_sequence_number_);
 829   const QuicPacketSequenceNumber index_of_first_21_contribution =
 830       std::min<QuicPacketSequenceNumber>(21, last_index);
 831   // Bit pattern of consecutively received packets that is maintained as we scan
 832   // through the received_packets_ vector. Less significant bits correspond to
 833   // less recent packets, and only the low order 21 bits are ever defined.
 834   // Bit is 1 iff corresponding packet was received.
 835   int packet_pattern_21 = 0;
 836   // Zero is an invalid packet sequence number.
 837   DCHECK(!received_packets_[0]);
 838   for (size_t i = 1; i <= last_index; ++i) {
 839     if (received_acks_[i])
 840       is_an_ack_histogram->Add(i);
 841     else
 842       is_not_ack_histogram->Add(i);
 843
 844     packet_pattern_21 >>= 1;
 845     if (received_packets_[i]) {
 846       packet_arrived_histogram->Add(i);
 847       packet_pattern_21 |= (1 << 20);  // Turn on the 21st bit.
 848     } else {
 849       packet_missing_histogram->Add(i);
 850     }
 851
 852     if (i == index_of_first_21_contribution) {
 853       AddTo21CumulativeHistogram(first_cumulative_packet_histogram,
 854                                  packet_pattern_21, i);
 855     }
 856     // We'll just record for non-overlapping ranges, to reduce histogramming
 857     // cost for now.  Each call does 21 separate histogram additions.
 858     if (i > 21 || i % 21 == 0) {
 859       AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram,
 860                                  packet_pattern_21, 21);
 861     }
 862
 863     if (i < 6)
 864       continue;  // Not enough packets to do any pattern recording.
 865     int recent_6_mask = packet_pattern_21 >> 15;
 866     DCHECK_LT(recent_6_mask, 64);
 867     if (i == 6) {
 868       Get6PacketHistogram("First6_")->Add(recent_6_mask);
 869       continue;
 870     }
 871     // Record some overlapping patterns, to get a better picture, since this is
 872     // not very expensive.
 873     if (i % 3 == 0)
 874       six_packet_histogram->Add(recent_6_mask);
 875   }
 876 }
 877
 878 }  // namespace net