net/quic/quic_connection_logger.cc

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