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