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