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